Served eth_getLogs err="context canceled"

[eduadiez]

System information

Geth version: 1.9.8-stable-d62e9b28
OS & Version: Linux

Expected behaviour

Be able to get the logs from 0x266BFdb2124A68beB6769dC887BD655f78778923 smartcontract since block 0x7A2CCB related to the filter 0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208.
This are the results that I get with Parity v2.5.10-stable:

eduadiez~ $ time curl -X POST  -H "Content-Type: application/json"  --data '{"jsonrpc":"2.0","method":"eth_getLogs","params":[{"address":"0x266BFdb2124A68beB6769dC887BD655f78778923","fromBlock":"0x7A2CCB","topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"]}],"id":74}'  http://fullnode.dappnode:8545
{"jsonrpc":"2.0","result":[{"address":"0x266bfdb2124a68beb6769dc887bd655f78778923","blockHash":"0x3cd8bca571cd0d57967ae6a3f944a271a815ea97992ea01b86c5aa987d021dcd","blockNumber":"0x7a2ccb","data":"0xad6826e119f6a15caa9eb1c5c450c97ef03906b26a65c04c822a1cf0b9cdefc10000000000000000000000000000000000000000000000000000000000000060000000000000000000000000e1d145eda2845e0917c305525d8ee7cc208c029100000000000000000000000000000000000000000000000000000000000000116c696768746e696e672d6e6574776f726b000000000000000000000000000000","logIndex":"0x1b","removed":false,"topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"],"transactionHash":"0xf329519b9a88c2ad5b82da769cf3479c48858e1d0058b5118c8eae61615cd1be","transactionIndex":"0x25","transactionLogIndex":"0x7","type":"mined"},{"address":"0x266bfdb2124a68beb6769dc887bd655f78778923","blockHash":"0xfe6e2bc524c885f82108b5680ebf11a6b4733eb398ab21a242939904b5e58dad","blockNumber":"0x818fb3","data":"0x1b9bd7546b166172b18b5f4cbfbd4d76ca340c60a698d2813f1b37513505789400000000000000000000000000000000000000000000000000000000000000600000000000000000000000006c4a0d357d8f590bacce42a4a497835beea2967b00000000000000000000000000000000000000000000000000000000000000046765746800000000000000000000000000000000000000000000000000000000","logIndex":"0x55","removed":false,"topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"],"transactionHash":"0xf307ed2f9bd08fb82f6994ad3ec419ad4b49a6521800ed9c1f7a20ef7b05db4e","transactionIndex":"0x81","transactionLogIndex":"0x7","type":"mined"},{"address":"0x266bfdb2124a68beb6769dc887bd655f78778923","blockHash":"0x4781a43d04c78caa143a5399c9e4375eb048d70051dfeed8ec38bf8b16d49488","blockNumber":"0x88f1f5","data":"0x8f8eb5744c9c9f62af04b6b00ef91c8270b8ec5c80c78c639149786d6482f63600000000000000000000000000000000000000000000000000000000000000600000000000000000000000007e538ebb507d56de0fb6c573d9be0f9cdec5c528000000000000000000000000000000000000000000000000000000000000001274727573746c696e65732d6d6f6e69746f720000000000000000000000000000","logIndex":"0x8a","removed":false,"topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"],"transactionHash":"0x1e50879e31384cc983bdd0384334c7c32ebc88de30c16d5f0f9237acfe4cbe65","transactionIndex":"0x78","transactionLogIndex":"0x8","type":"mined"},{"address":"0x266bfdb2124a68beb6769dc887bd655f78778923","blockHash":"0x8c5eeffbaed1893427821d1f98b8085b475c8727db3cd09998a1fa8d7fe31853","blockNumber":"0x88f222","data":"0xd88b3d6ce3b30af8a8a6ee417f1618117bd2ff9dad4788f51d6d76b1f12726d1000000000000000000000000000000000000000000000000000000000000006000000000000000000000000038bcfc1a7b62cae7970e04b08ed2b8d8b929bbb0000000000000000000000000000000000000000000000000000000000000000a74727573746c696e657300000000000000000000000000000000000000000000","logIndex":"0x38","removed":false,"topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"],"transactionHash":"0x10a76e0604bb5a6047bc8c1b60ec2723e79adcab456cda97b6cfebeaeaf7d546","transactionIndex":"0x36","transactionLogIndex":"0x8","type":"mined"},{"address":"0x266bfdb2124a68beb6769dc887bd655f78778923","blockHash":"0xc84b9167c3e45e41be5e3b14e7a1774958c3780971d8ec82e2696f59f1ce5353","blockNumber":"0x88f251","data":"0xc1bea90834a069a38cf2d9ac689d2064a5c64604c7f76ea352d82b2eca00c48d00000000000000000000000000000000000000000000000000000000000000600000000000000000000000001e41779cfee567b7fac349ef0b5f5cdf3bda25b8000000000000000000000000000000000000000000000000000000000000001174727573746c696e65732d627269646765000000000000000000000000000000","logIndex":"0x3a","removed":false,"topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"],"transactionHash":"0x72f86b06651a4f36b0326cb82b9a10fb8ee950c19ac8e3fc76e8ede5cb95e301","transactionIndex":"0x2a","transactionLogIndex":"0x8","type":"mined"},{"address":"0x266bfdb2124a68beb6769dc887bd655f78778923","blockHash":"0x76865137a37559565e46c8e90213fa6dff2ed3c821decc6ed5ef224f0135b933","blockNumber":"0x88f271","data":"0x377022fdf542b656429e5f3965f4cdc72bf5241aa27d13209c1f1ec0c06ef5c20000000000000000000000000000000000000000000000000000000000000060000000000000000000000000cc9a190e06531bd6a68ce14e2e2a87f75bfe473f000000000000000000000000000000000000000000000000000000000000001374727573746c696e65732d6e6574737461747300000000000000000000000000","logIndex":"0x40","removed":false,"topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"],"transactionHash":"0xe5866770f8fff8fa270f13d8afd6dbdf1226a167baff0b04931f8f2066c92254","transactionIndex":"0x2c","transactionLogIndex":"0x8","type":"mined"},{"address":"0x266bfdb2124a68beb6769dc887bd655f78778923","blockHash":"0x2cff1f560db8a8fe0189c0f804f5d8d2472a09783821d942b3d52bc63ba2fe33","blockNumber":"0x88f3b2","data":"0x0b7cbabfabdb9154bada1192c34ed6d29f45ab8e9923e9005798ec716c50195e0000000000000000000000000000000000000000000000000000000000000060000000000000000000000000b191457a257c1734f18608d744ddfd120979bb2f000000000000000000000000000000000000000000000000000000000000001474727573746c696e65732d76616c696461746f72000000000000000000000000","logIndex":"0x68","removed":false,"topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"],"transactionHash":"0x6168be4f1a30d2499eb5ef4f55c212d608ab4d62d387aa08c8bf21857c46c214","transactionIndex":"0x72","transactionLogIndex":"0x8","type":"mined"},{"address":"0x266bfdb2124a68beb6769dc887bd655f78778923","blockHash":"0xe575ddaa16b3fcc5a421ba47d96978a9320b561b9dfefcfb96eda321b03e010c","blockNumber":"0x89eb53","data":"0x4feb3c0b0b2dc37cf7a616dd81954cbd29c175aa073bdba8ef2b55ef0b13419d000000000000000000000000000000000000000000000000000000000000006000000000000000000000000039ef4e2d2d62134b1b71103fa7a895fda023fe4d000000000000000000000000000000000000000000000000000000000000000c697066732d636c75737465720000000000000000000000000000000000000000","logIndex":"0x62","removed":false,"topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"],"transactionHash":"0x4087d76b686748d2ae6626a032614ce2a402a207fbbf099451d17f6b2cade4e8","transactionIndex":"0x46","transactionLogIndex":"0x8","type":"mined"},{"address":"0x266bfdb2124a68beb6769dc887bd655f78778923","blockHash":"0x19347ef9385b559c306ff67919d0c9832b864e92c8df60fb49abee6059003f77","blockNumber":"0x89eca2","data":"0x2e3ecc5ebebf071ec6ecbb0ce30267d59367ac69b8dbc2f7156672a7398e5a5b000000000000000000000000000000000000000000000000000000000000006000000000000000000000000032e1ef330df9840c4a689ba9affb22d6762aae2b000000000000000000000000000000000000000000000000000000000000000b697066732d70696e6e6572000000000000000000000000000000000000000000","logIndex":"0x7d","removed":false,"topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"],"transactionHash":"0xae20a4f86014d453b2480ecee692ae9dd182c64000a88b07738844dcb09d4dd7","transactionIndex":"0x67","transactionLogIndex":"0x8","type":"mined"}],"id":74}

real	0m28.315s
user	0m0.005s
sys	0m0.011s

Actual behaviour

I tried in several machines with the same geth version fully synchronised and I get this response:

eduadiez~ $ time curl -X POST  -H "Content-Type: application/json"  --data '{"jsonrpc":"2.0","method":"eth_getLogs","params":[{"address":"0x266BFdb2124A68beB6769dC887BD655f78778923","fromBlock":"0x7A2CCB","topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"]}],"id":74}'  http://fullnode.dappnode:8545
curl: (52) Empty reply from server

real	4m59.892s
user	0m0.011s
sys	0m0.024s

Steps to reproduce the behaviour

curl -X POST  -H "Content-Type: application/json"  --data '{"jsonrpc":"2.0","method":"eth_getLogs","params":[{"address":"0x266BFdb2124A68beB6769dC887BD655f78778923","fromBlock":"0x7A2CCB","topics":["0x526d4ccf8c3d7b6f0b6d4cc0de526d515c87d1ea3bd264ace0b5c2e70d1b2208"]}],"id":74}'  

Backtrace

INFO [12-04|15:37:41.913] Imported new chain segment               blocks=1  txs=164  mgas=9.934   elapsed=8.326s    mgasps=1.193   number=9050020 hash=1bab4a…4d45c4 dirty=459.72MiB
INFO [12-04|15:38:00.234] Imported new chain segment               blocks=1  txs=173  mgas=9.940   elapsed=4.669s    mgasps=2.129   number=9050021 hash=e19cc7…8da4e7 dirty=459.79MiB
WARN [12-04|15:38:01.916] Served eth_getLogs                       conn=172.33.0.2:52062  reqid=1411 t=2m0.04507267s   err="context canceled"
INFO [12-04|15:38:10.696] Imported new chain segment               blocks=1  txs=25   mgas=0.992   elapsed=45.965ms  mgasps=21.585  number=9050022 hash=c8fa1a…23edd7 dirty=459.22MiB
INFO [12-04|15:38:23.229] Deep froze chain segment                 blocks=5  elapsed=622.084ms number=8960021 hash=1f7947…90b4f7````

[karalabe]

This seems to be a nice issue. We'll need to take a closer look into this.

[eduadiez]

Thanks @karalabe. Let me know if I can help with anything

[rjl493456442]

Maybe this PR can help with it? #16070

[kutysam]

Hi,

We are also facing a similar issue.
The two queries below have also been ran on an archive node.
Having a higher fromblock works but lower fromblock doesn't work.

Works (Block 10870000)

curl -v --location --request POST 'http://localhost:8545' \
--header 'Content-Type: application/json' \
--data-raw '{
    "jsonrpc": "2.0",
    "method": "eth_getLogs",
    "params": [
        {
            "fromBlock": "0xA5DCF0",
            "address": [
                "0x5C69bEe701ef814a2B6a3EDD4B1652CB9cc5aA6f"
            ]
        }
    ],
    "id": 1
}'

---

Not Working (Block 10800000) - curl: (52) Empty reply from server

curl -v --location --request POST 'http://localhost:8545' \
--header 'Content-Type: application/json' \
--data-raw '{
    "jsonrpc": "2.0",
    "method": "eth_getLogs",
    "params": [
        {
            "fromBlock": "0xA4CB80",
            "address": [
                "0x5C69bEe701ef814a2B6a3EDD4B1652CB9cc5aA6f"
            ]
        }
    ],
    "id": 1
}'

[mrice32]

@karalabe We're seeing a similar issue when we make log queries that span more than ~400k blocks (we default to fromBlock: 0). Note: we updated our docker image yesterday and we're running a fairly standard non-archival node. Recognizing that querying geth with fromBlock: 0 isn't ideal, is there a way to either:

1. Make geth respond to queries without timing out, even if they take a long time/a lot of resources (we've extended the read timeout and still see the same issue)?
2. Determine how small queries need to be to guarantee that geth will not throw this error?

Edit: The context canceled was coming from a timeout on the client side. It also required increasing the write timeout in geth to keep it from silently timing out on geth's end. This isn't an issue for us, though.

[miohtama]

It also required increasing the write timeout in geth to keep it from silently timing out on geth's end.

I am also facing err="context canceled"

Are there any starting points where one could tune what timeouts and such settings in geth could be tuned for this?

[miohtama]

I did an example on web3.py how to throttle down requests on HTTP timeout reply. Not ideal, but works for now. Ultimately would be nice to be able to have more control over how much data can be requested at once.

ethereum/web3.py#1910

[s1na]

Geth silently closed connections on timeout which caused confusion. With #25457 merged, geth will return a timeout error. You can extend the WriteTimeout if you want your node to run longer queries. Closing.