Missing events in newly sync'd chain

[dabooz]

System information

Geth version: 1.5.5
OS & Version: Ubuntu Linux 14.04
Commit hash : (if develop)

Expected behaviour

eth_getFilterLogs returns all events in the blockchain for a given solidity contract (address).

Actual behaviour

For a newly sync'd chain, sometimes the events are present sometimes they aren't. To clarify, the chain exists and it definitely has events in it from the given solidity contract. When a NEW geth client is started, and syncs with the chain, sometimes that client will be returned the events on the getFilterLogs call and sometimes it wont. I havent been able to narrow down further yet.

Steps to reproduce the behaviour

Not exactly sure because I can't narrow it down.

1. install a smart contract onto the chain.
2. call a non-constant method on the contract that creates 1 or more events.
3. verify that the method completed successfully
4. Start up a new geth client (and wait for syncing to complete) and then run the following steps on the new client
5. create a filter (eth_newFilter) by smart contract address to retrieve the events
6. invoke eth_getFilterLogs with the filter created in 5.
7. sometimes the events from 2 are returned sometimes they arent.

Backtrace

there is none

[dabooz]

Still trying to narrow this down. I turned on verbosity level 6 tracing in geth and am unable to recreate the problem. This tells me the problem is related to a lock or other timing thing inside geth.

[dabooz]

I kept trying and managed to recreate it with verbosity 5 after a lot of tries. I have a geth log and my own logs. I know what block the events are supposed to be in (151923 and 151965). I scanned the logs for 151923 and 151965, and I see these messages:

I0113 20:17:03.718081 eth/peer.go:209] Peer 478a75e6f4c01f2a [eth/63] fetching 192 headers from #151873, skipping 0 (reverse = false)

I0113 20:17:06.844151 core/database_util.go:344] stored header #151923 [fe491cfb…]

I0113 20:17:06.849632 core/database_util.go:344] stored header #151965 [4d2c69ad…]

there are no messages (in the geth log) at the time my code was making calls to eth_newFilter and getFilterLogs. The calls occurred 6 seconds after the above messages. Here's messages from my logs:
I0113 20:17:12.327527 159 rpc.go:127] Invoking eth_newFilter with map[jsonrpc:2.0 id:1 method:eth_newFilter params:[map[toBlock:0x25751 topics:[] address:0x28f3e5b47e2d0b1d1edd0b0b13b20836c4bd1e67 fromBlock:0x1]]]

I0113 20:17:12.328263 159 rpc.go:143] Response to map[jsonrpc:2.0 id:1 method:eth_newFilter params:[map[topics:[] address:0x28f3e5b47e2d0b1d1edd0b0b13b20836c4bd1e67 fromBlock:0x1 toBlock:0x25751]]] is {"jsonrpc":"2.0","id":"1","result":"0x4c7632570b012db4d30e083483ca1e3a"}

I0113 20:17:12.328298 159 event_log.go:276] Filter 0x4c7632570b012db4d30e083483ca1e3a for 0x28f3e5b47e2d0b1d1edd0b0b13b20836c4bd1e67 using client &{0xc82039e270 map[method:eth_newFilter params:[map[address:0x28f3e5b47e2d0b1d1edd0b0b13b20836c4bd1e67 fromBlock:0x1 toBlock:0x25751 topics:[]]] jsonrpc:2.0 id:1] 0xc82039e300}

I0113 20:17:12.328323 159 rpc.go:127] Invoking eth_getFilterLogs with map[params:[0x4c7632570b012db4d30e083483ca1e3a] jsonrpc:2.0 id:1 method:eth_getFilterLogs]
I0113 20:17:12.328996 159 rpc.go:143] Response to map[jsonrpc:2.0 id:1 method:eth_getFilterLogs params:[0x4c7632570b012db4d30e083483ca1e3a]] is {"jsonrpc":"2.0","id":"1","result":[]}

Given the large span of blocks covered by the filter (fromBlock:0x1 toBlock:0x25751), I am surprised that getFilterLogs came back so quickly. I suspect a lock was mishandled resulting in the call returning quickly....obviously a guess on my part. I dont know the code.

[bas-vk]

This is fixed in 1.5.6.

[dabooz]

Can you point me to a commit with the fix in it? 1.5.6 is also broken for us, so if I can patch 1.5.5 I might decide to do that.

[fjl]

The commit is 2fed476. We strongly recommend that you skip 1.5.6 because it contains known regressions in the RPC API which are fixed in 1.5.7.

[ethernomad]

Are you using --fast ?

[dabooz]

Yes we are using --fast, and yes we are aware of the 156 regressions. We are on 157 now and eth seems to be stable. I was only asking about a patch for this for 155 in case 157 was unstable like 156.

[ethernomad]

Fast sync does not import logs #3500

[fjl]

@ethernomad Fast sync is expected to import logs. We don't know what's wrong in #3500, but it's unrelated to this issue.

[ethernomad]

Ah okay. Here's further info: https://www.reddit.com/r/ethereum/comments/5dwdeb/blobstore_immutable_storage_on_ethereum/da7wcn1/?st=iy1u5b4l&sh=6aedb9f1