Geth error: debug_traceTransaction insufficient balance to pay for gas

[jcortejoso]

Hi! We are running blockscout syncing with a POA based on Geth. I am running a local full-synced node which exposes rpc and ws api and Blockscout connects locally. When I run blockscout I get some errors when blockscout is invoking the rpc method trace_replaytransaction, and keeps this error appearing infinitely with different transactions.

These are the error traces I see:
Blockscout during execution:

(...)
2019-09-24T10:25:34.714 application=indexer fetcher=internal_transaction count=10 error_count=10 [error] failed to fetch internal transactions for transactions: [%{code: -32000, data: %{block_number: 194955, transaction_hash: "0x47e06d585eda2b323c03ecb8e290841792fa6323446aac843e800ce6f356092e", transaction_index: 1}, message: "transaction dea76dba9b2d469aa165e567450d42695200cc8860cd2221b7bef808580ed808 failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 194955, transaction_hash: "0xdea76dba9b2d469aa165e567450d42695200cc8860cd2221b7bef808580ed808", transaction_index: 0}, message: "tracing failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 179485, transaction_hash: "0x076129ab113980122dbab48189d39e851f9b968317af249c755c6e375addd444", transaction_index: 1}, message: "transaction d82aaf5e48bea4fe2315f33e7d7712ac7e65a1892ab6195a32aa59ed1f2aadf7 failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 179480, transaction_hash: "0x0fe94ce2b596b92ccbadeaf25250d3e5fdbd04691721ddca273a25371992ed95", transaction_index: 0}, message: "tracing failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 179480, transaction_hash: "0x4d5daf0a838bb485bbb91f4fe5b877b416f2172938dd4d36f7c941019bc55bb9", transaction_index: 1}, message: "transaction 0fe94ce2b596b92ccbadeaf25250d3e5fdbd04691721ddca273a25371992ed95 failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 179485, transaction_hash: "0xd82aaf5e48bea4fe2315f33e7d7712ac7e65a1892ab6195a32aa59ed1f2aadf7", transaction_index: 0}, message: "tracing failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 179315, transaction_hash: "0x175cf08615280b323bae5a7a2f0e85dd8a96baf989323163cfd234c5c9d1a0f5", transaction_index: 0}, message: "tracing failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 179309, transaction_hash: "0x51995ac3bce1358de1ab43d48e3ee535bb1e88c29e47181d73dcb0a8ce8a5d04", transaction_index: 0}, message: "tracing failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 179310, transaction_hash: "0xa65298e585fb383508cc8b9bf22dc27f49e1b363fbfb505fb6013a5597d02fb1", transaction_index: 0}, message: "tracing failed: insufficient balance to pay for gas"}]
2019-09-24T10:25:35.062 application=indexer fetcher=internal_transaction count=10 error_count=10 [error] failed to fetch internal transactions for transactions: [%{code: -32000, data: %{block_number: 203897, transaction_hash: "0xddd0cf45aafa2d4d96f6cdf51beb20ecf9a63fa395ba6be732d189ef910cf969", transaction_index: 2}, message: "transaction 2e12dfc93e67ffd39c905dcc0960b9533a431cc7e37569c9241fab7968a77462 failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 200851, transaction_hash: "0x124cb2c080ddc11f28898f3bedff5c9750e7cce75b9ca7eaac2b2f87179c6baf", transaction_index: 0}, message: "tracing failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 200855, transaction_hash: "0x28a92836abac22a5b4eb0a87ec2fed92b5785cc276e4360e69944bfd7b29bf2f", transaction_index: 1}, message: "transaction 7d2a8d63b294dd92a8b4e346f04bc5892c70b14dafe62af9163635830adcdd59 failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 200851, transaction_hash: "0x7545a3e28b594e5469f4b9df767e908a4e9c155756b02cc2955ac0a1b8391095", transaction_index: 1}, message: "transaction 124cb2c080ddc11f28898f3bedff5c9750e7cce75b9ca7eaac2b2f87179c6baf failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 200846, transaction_hash: "0x7b5cfc162d8a3c4d7b7f6aefcd154625c7531f7d2eb680a8bfbbdd812f94d0ef", transaction_index: 0}, message: "tracing failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 200855, transaction_hash: "0x7d2a8d63b294dd92a8b4e346f04bc5892c70b14dafe62af9163635830adcdd59", transaction_index: 0}, message: "tracing failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 200079, transaction_hash: "0x03f832990fcc010271666df83d8338730949b91d0cf360589a50c42df8147d60", transaction_index: 3}, message: "transaction 9ecff7953530e8eb2b5ad3c21151132bf908ec10948d9bd5321badd4c0dd2ef6 failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 200079, transaction_hash: "0x3892b691a7633c806d452f0999e813e0ac4bd909da5cef01ef8b461fa8c25b30", transaction_index: 1}, message: "transaction 9ecff7953530e8eb2b5ad3c21151132bf908ec10948d9bd5321badd4c0dd2ef6 failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 200079, transaction_hash: "0x9ecff7953530e8eb2b5ad3c21151132bf908ec10948d9bd5321badd4c0dd2ef6", transaction_index: 0}, message: "tracing failed: insufficient balance to pay for gas"}, %{code: -32000, data: %{block_number: 200079, transaction_hash: "0xdb2e8b42dc7958bc3c8fe0009353ac547c50ca7239a79289a0aab31d33f09418", transaction_index: 2}, message: "transaction 9ecff7953530e8eb2b5ad3c21151132bf908ec10948d9bd5321badd4c0dd2ef6 failed: insufficient balance to pay for gas"}]
(...)

Blockscout when finishing the process:

(...)
2019-09-24T10:31:52.479 fetcher=internal_transaction count=10 [error] Task #PID<0.32286.1> started from Indexer.Fetcher.InternalTransaction terminating
** (EthereumJSONRPC.DecodeError) Failed to decode Ethereum JSONRPC response:

  request:

    url: http://localhost:8545

    body: [{"id":0,"jsonrpc":"2.0","method":"debug_traceTransaction","params":["0x1d8bb03f17912319b3d7710f4e132aedc51f68f38fcb1dacd312cbe58ed10ad0",{"disableMemory":true,"disableStack":true,"disableStorage":true,"tracer":"// tracer allows Geth's `debug_traceTransaction` to mimic the output of Parity's `trace_replayTransaction`\n{\n    // The call stack of the EVM execution.\n    callStack: [{}],\n\n    // step is invoked for every opcode that the VM executes.\n    step(log, db) {\n        // Capture any errors immediately\n        const error = log.getError();\n\n        if (error !== undefined) {\n            this.fault(log, db);\n        } else {\n            this.success(log, db);\n        }\n    }

  response:

    status code: 200

    body:

    (ethereum_jsonrpc) lib/ethereum_jsonrpc/http.ex:117: EthereumJSONRPC.HTTP.decode_json/1
    (ethereum_jsonrpc) lib/ethereum_jsonrpc/http.ex:69: EthereumJSONRPC.HTTP.chunked_json_rpc/3
    (ethereum_jsonrpc) lib/ethereum_jsonrpc/request_coordinator.ex:86: anonymous fn/3 in EthereumJSONRPC.RequestCoordinator.perform/4
    (ethereum_jsonrpc) lib/ethereum_jsonrpc/request_coordinator.ex:106: EthereumJSONRPC.RequestCoordinator.trace_request/2
    (ethereum_jsonrpc) lib/ethereum_jsonrpc/geth.ex:31: EthereumJSONRPC.Geth.fetch_internal_transactions/2
    (indexer) lib/indexer/fetcher/internal_transaction.ex:170: Indexer.Fetcher.InternalTransaction.run/2
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: &Indexer.BufferedTask.log_run/1
    Args: [%{batch: [{102088, <<29, 139, 176, 63, 23, 145, 35, 25, 179, 215, 113, 15, 78, 19, 42, 237, 197, 31, 104, 243, 143, 203, 29, 172, 211, 18, 203, 229, 142, 209, 10, 208>>, 0}, {101815, <<140, 144, 165, 36, 1, 68, 187, 97, 4, 147, 120, 86, 50, 78, 117, 66, 19, 21, 184, 235, 82, 79, 234, 185, 95, 85, 172, 114, 64, 216, 151, 30>>, 0}, {101794, <<207, 97, 201, 46, 40, 41, 192, 95, 207, 33, 128, 105, 194, 196, 172, 83, 51, 23, 141, 146, 121, 40, 157, 134, 79, 138, 170, 222, 135, 116, 156, 101>>, 0}, {100589, <<123, 209, 64, 48, 81, 68, 192, 26, 184, 190, 140, 169, 230, 86, 57, 77, 167, 97, 188, 206, 97, 235, 217, 233, 3, 77, 13, 172, 63, 153, 185, 25>>, 1}, {100589, <<133, 107, 82, 78, 144, 54, 168, 50, 246, 214, 82, 86, 234, 169, 143, 164, 33, 81, 4, 158, 4, 127, 133, 164, 220, 9, 42, 229, 212, 223, 83, 174>>, 3}, {100589, <<157, 165, 254, 190, 119, 201, 223, 109, 58, 104, 58, 188, 2, 47, 106, 201, 211, 125, 7, 15, 113, 233, 138, 32, 122, 206, 160, 160, 237, 58, 174, 89>>, 2}, {100592, <<248, 133, 31, 20, 57, 214, 211, 14, 202, 118, 233, 128, 63, 26, 73, 172, 65, 94, 146, 55, 229, 192, 63, 17, 89, 201, 32, 6, 199, 158, 28, 86>>, 1}, {97884, <<115, 90, 234, 56, 32, 241, 250, 1, 190, 186, 131, 103, 254, 95, 82, 209, 219, 9, 90, 63, 82, 12, 181, 78, 21, 135, 47, 83, 30, 213, 169, 24>>, 0}, {85179, <<76, 75, 112, 105, 75, 184, 3, 14, 239, 7, 81, 236, 201, 44, 14, 192, 201, 59, 43, 148, 58, 236, 235, 11, 102, 139, 132, 148, 234, 147, 65, 195>>, 0}, {105041, <<238, 23, 85, 241, 239, 40, 227, 167, 160, 138, 23, 132, 29, 196, 245, 29, 89, 198, 133, 201, 52, 34, 64, 74, 181, 158, 86, 182, 40, 39, 118, 69>>, 0}], callback_module: Indexer.Fetcher.InternalTransaction, callback_module_state: [transport: EthereumJSONRPC.HTTP, transport_options: [http: EthereumJSONRPC.HTTP.HTTPoison, url: "http://localhost:8545", http_options: [recv_timeout: 60000, timeout: 60000, hackney: [pool: :ethereum_jsonrpc]]], variant: EthereumJSONRPC.Geth], metadata: [fetcher: :internal_transaction]}]
(...)

Geth node:

(...)
ERROR[09-24|08:25:35.057] Error in calling the EVM                 funcName=balanceOf transactionData=0x70a08231000000000000000000000000b1363c9eafc29b00cd93526b0ea19600117554cf err="evm: execution reverted"
ERROR[09-24|08:25:35.057] Error when invoking evm function         err="evm: execution reverted"
ERROR[09-24|08:25:35.057] GetBalanceOf evm invocation error        leftoverGas=70 err="evm: execution reverted"
ERROR[09-24|08:25:35.057] Transaction failed to buy gas            err="insufficient balance to pay for gas"        gas=168880
ERROR[09-24|08:25:35.064] Error in calling the EVM                 funcName=balanceOf transactionData=0x70a08231000000000000000000000000b1363c9eafc29b00cd93526b0ea19600117554cf err="evm: execution reverted"
ERROR[09-24|08:25:35.064] Error when invoking evm function         err="evm: execution reverted"
ERROR[09-24|08:25:35.064] GetBalanceOf evm invocation error        leftoverGas=70 err="evm: execution reverted"
ERROR[09-24|08:25:35.064] Transaction failed to buy gas            err="insufficient balance to pay for gas"        gas=168880
ERROR[09-24|08:25:35.147] Error in calling the EVM                 funcName=balanceOf transactionData=0x70a082310000000000000000000000004eb4f69a6e9f2c3b20a5dcf5f8a31ab3f853fb1a err="evm: execution reverted"
ERROR[09-24|08:25:35.147] Error when invoking evm function         err="evm: execution reverted"
ERROR[09-24|08:25:35.147] GetBalanceOf evm invocation error        leftoverGas=70 err="evm: execution reverted"
ERROR[09-24|08:25:35.147] Transaction failed to buy gas            err="insufficient balance to pay for gas"        gas=158192
(...)

The errors keep appearing indefinitely. After some time running showing these errors the geth process dies because OutOfMemory (during the error the cpu starts throttling).
I have check some of the transactions of the errors and seems to be failed because out of balance to pay gas.

Environment

• Elixir & Erlang/OTP versions (elixir -version):

Elixir 1.9.1 (compiled with Erlang/OTP 22)```
* Operating System:
```-> uname -a
Darwin pucela.local 18.7.0 Darwin Kernel Version 18.7.0: Tue Aug 20 16:57:14 PDT 2019; root:xnu-4903.271.2~2/RELEASE_X86_64 x86_64

• Blockscout Version/branch: Commit b544895 with merging this PR and some minor template modification.
  Env variables:

export NETWORK="Celo"
export SUBNETWORK="Alfajores"
export ETHEREUM_JSONRPC_VARIANT="geth"
export ETHEREUM_JSONRPC_HTTP_URL="http://localhost:8545"
export ETHEREUM_JSONRPC_TRACE_URL="http://localhost:8545"
export ETHEREUM_JSONRPC_WS_URL="ws://localhost:8546"
export COIN=cGLD

• Geth options:
  I am running geth using docker with the next parameters:

-> docker run -p 127.0.0.1:8545:8545 -p 127.0.0.1:8546:8546 -p 30303:30303 -p 30303:30303/udp -v `pwd`:/root/.celo us.gcr.io/celo-testnet/celo-node:alfajores\
 --verbosity 1\
 --trace /dev/null\
 --networkid 44782\
 --syncmode full\
 --rpc\
 --rpcaddr 0.0.0.0\
 --rpcapi eth,net,web3,debug,admin,personal,txpool\
 --rpccorsdomain='*'\
 --rpcvhosts='*'\
 --ws\
 --wsaddr 0.0.0.0\
 --wsorigins='*'\
 --wsapi=eth,net,web3,debug\
 --lightserv 90\
 --lightpeers 100\
 --maxpeers 101\
 --etherbase b547be336501243601fdf0b3bd776276ae75e315\
 --ethstats=pucela.local:1234@192.168.11.65:3000

-> geth version (inside container)
Geth
Version: 1.8.23-stable
Architecture: amd64
Network Id: 1
Go Version: go1.11.13
Operating System: linux
GOPATH=
GOROOT=/usr/local/go

Steps to reproduce

If interested I can give you details to connect to our local POA

Expected behaviour

Blockscout and geth can keep running

Actual behaviour

Geth dies after some minutes due to OOM error.

Thank you!.

[jcortejoso]

Think this is solved now. It was related with a bug in the geth client.