search

ethereumjs / ethereumjs-blockstream

Reliable stream of Ethereum blocks
MIT License
80 stars 18 forks source link

Error: received log with same block number but index newer than previous index #17

Closed mohoff closed 6 years ago

mohoff commented 6 years ago

Hi, I'm getting an error when using the 0x library and its zeroEx.exchange.subscribe. The error output points to ethereumjs-blockstream, so I'm just putting the open 0x issue for the details:

https://github.com/0xProject/0x-monorepo/issues/693

Let me know if you need more info. Thanks for investigating!

MicahZoltu commented 6 years ago

I have seen this one before, though I admit that I don't remember how the issue was resolved. It ended up being the caller was doing something unexpected and Blockstream ended up confused by it I believe. @epheph do you remember how you resolved this when you ran into it with Augur Node?

MicahZoltu commented 6 years ago

@mohoff Can you see what version of ethereumjs-blockstream you are using? I think this may have been a bug in an older version.

MicahZoltu commented 6 years ago

If you are using 2.0.6 (per https://github.com/0xProject/0x-monorepo/blob/development/packages/contract-wrappers/package.json#L82) then I am reasonably confident that is the problem. If it is what I think it is, then it was fixed in https://github.com/ethereumjs/ethereumjs-blockstream/pull/13 which is in v4.0.0 (https://github.com/ethereumjs/ethereumjs-blockstream/commit/6580081619f8518c5f242262266554754ab12e3a)

MicahZoltu commented 6 years ago

Duplicate of https://github.com/ethereumjs/ethereumjs-blockstream/issues/7 I believe. Leaving open for now while awaiting feedback from @mohoff to verify that this is in fact a duplicate.

mohoff commented 6 years ago

Thanks @MicahZoltu for your fast reply! Yeah, 0x.js@0.37.2, which I am using, includes ethereumjs-blockstream@2.0.7.

However, I don't see how my code involves multiple filters, as described in #7 / #13 . Seems like only one filter is used (https://github.com/0xProject/0x-monorepo/blob/v2-prototype/packages/contract-wrappers/src/contract_wrappers/contract_wrapper.ts#L78). But you're the expert here ;)

MicahZoltu commented 6 years ago

@mohoff Do you have the ability to easily reproduce and debug the issue? If so, I would be curious to know what BlockAndLogStreamer.logFilters contains (https://github.com/ethereumjs/ethereumjs-blockstream/blob/master/source/block-and-log-streamer.ts#L22). In particular, does it contain only a single item, or does it contain multiple items.

Glancing at the 0x code you linked, it appears the only place that a filter is added is here and there appear to be guards in place to prevent that from ever being called twice, so your assertion that multiple filters aren't being added is certainly reasonable. None the less, it would be good to verify with certainty (via the check I mentioned above) just to make sure before we try to debug ethereumjs-blockstream too deeply (mainly because digging into it is hard).

Another piece of debugging that would be useful would be to check to see what is triggering the addNewLogsToHead call, in particular, whether it is an existing block being added twice or somehow that callback is being called twice with the same logs, or if logs were fetched multiple times. I still feel like the most likely situation is somehow ending up with multiple subscriptions, which that version doesn't support, mainly because I can't find any other code paths that lead to the problem.

Lastly, do you have a turn-key repro case that I could fire up? Ideally something that doesn't require me to spin up some large/complicated infrastructure to debug. :)

mohoff commented 6 years ago

@MicahZoltu I'm not too deep into this but I logged the filters to console (inside addLogFilter()), That's the output:

{ 'log filter token c2e50d35-360c-4302-ab48-1c1dde5c08cf': {} }

So from that, it looks like this function is only called once and logFilters only contains one entry. Does this help? Also, I don't know where to find addNewLogsToHead. Any pointer? Would be great if you can shortly outline the steps to do in order to give you the desired debug info.

With repro case, you mean more than what I already posted in the 0x open issue? What do you need? (not familiar with all this sorry)

MicahZoltu commented 6 years ago

I haven't actually used the 0x libraries before, so I don't know how to setup a test environment with it. That is, I don't know what to do with that code snippet you provided. I'm guessing I would need to setup a new project, instantiate and configure zeroEx in some way (point it at main-net?), then call the code you provided? If you have a project I can checkout that reproduces the problem that may be enough to get me started.

MicahZoltu commented 6 years ago

Note: If you upgrade to v4.0.0 I am pretty confident that the error will go away. However, it would be good to understand how you got into this situation since it appears you aren't double subscribing.

mohoff commented 6 years ago

@MicahZoltu Understood. I set up a repo for you with my script: https://github.com/mohoff/0xTestScripts (still on version 2.0.7).

I upgraded to 4.0.0 and now I get the following:

Error: received log with same block number (91756809) but index (0) is the same or older than previous index (528)
    at ensureOrder (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:147:15)
    at /home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:91:33
    at step (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:32:23)
    at Object.next (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:13:53)
    at step (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:17:97)
    at Object.next (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:13:53)
    at /home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:7:71
    at new Promise (<anonymous>)
    at __awaiter (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:3:12)
    at addNewLogsToHead (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:78:76)
    at Object.<anonymous> (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:52:42)
    at step (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:32:23)
    at Object.next (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:13:53)
    at fulfilled (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:4:58)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:188:7)

So I think same error with a better error message. Do you have an idea?

MicahZoltu commented 6 years ago

I'll see if I can use your repo to reproduce the bug on my machine and debug it to figure out what is going on. It is late here though, so I may not figure it out until tomorrow.

MicahZoltu commented 6 years ago

@mohoff I cloned your repo, pointed it at one of my nodes (instead of Infura since I don't have an API key) and created a new account (new mnemonic) then ran index.js. It appears to run, but it just sits at Results: with nothing happening. Do I need to do something to trigger it?

mohoff commented 6 years ago

Good, seems to work! No, it's just waiting for an event emitted on the 0x Exchange.sol contract. So every few seconds/minutes, something should happen (in our case, there should be the error popping once the first trade happened after you started the script). Do you get any output if you wait for a bit?

MicahZoltu commented 6 years ago

Nope, sitting here for about 10 minutes and nothing has come through, just Results: and nothing after that.

mohoff commented 6 years ago

Hmm so either you're unlucky or something is not going through your local node. Your local node is on mainnet, too? In my code, you can quickly change the network with setting the network id in the beginning. Just in case your local node is syncing a testnet. If so, you would also need to update the token contract addresses in the script (currently the mainnet addresses are used in the script)

EDIT: I'm getting the error when waiting ~1-3 minutes, just happened again. So something else is wrong...

Error: received log with same block number (91759170) but index (0) is the same or older than previous index (144)
MicahZoltu commented 6 years ago

Yep, I'm on mainnet. I have also debugged a bit and verified that I am seeing logs, but they are all filtered out (it appears the code is looking specifically for ZRX:WETH trades).

MicahZoltu commented 6 years ago

Issue reproduced with Infura pretty quickly. Must be something with the way it works...

mohoff commented 6 years ago

Oh I see. Yeah, AFAIK Infura supports most but not all JSON RPC methods. Can't find the list of supported and unsupported methods anymore...

EDIT: some more info: https://github.com/INFURA/infura/blob/master/docs/source/index.html.md

MicahZoltu commented 6 years ago

Hmm, I'm now unable to reproduce the problem again, even using Infura. I wonder if it is related to https://github.com/ethereumjs/ethereumjs-blockstream/issues/10? That race should get hit incredibly rarely though, and you indicated that you are seeing this fairly often?

MicahZoltu commented 6 years ago

The only two functions that are needed are eth_getBlockByHash and eth_getLogs, both of which Infura supports, so I don't think it is an issue of not supporting something we need. Though, it is possible that something weird is happening in 0x library around Infura that causes it to behave differently?

mohoff commented 6 years ago

Weird. Yes, I'm seeing it every time. Don't even know how the normal log output looks... Because of that, I'm not sure about #10 since I see the error all the time.

MicahZoltu commented 6 years ago

Can you pop into Gitter.im so we can discuss more real-time? I'm still struggling to reproduce the problem.

MicahZoltu commented 6 years ago

I did some digging and this appears to be a dupe of https://github.com/ethereumjs/ethereumjs-blockstream/issues/10 after all. The flow goes something like this:

  1. Receive block 1234 with hash 0xABC
  2. Trigger addition of block 1234 with hash 0xABC
  3. Fetch logs for block 1234, get logs associated with hash 0xDEF
  4. Receive block 1234 with hash 0xDEF
  5. Trigger removal of block 1234 with hash 0xABC
  6. Trigger removal of logs with hash 0xABC (there are none!)
  7. Trigger addition of block 1234 with hash 0xDEF
  8. Fetch logs for block 1234, get logs associated with hash 0xDEF
  9. Fail because the stream already has the logs, which is an indicator that something went horribly wrong (which it did, we got logs for a block that had never shown up yet).
mohoff commented 6 years ago

A Is different hash the result of a reorg of blocks right? I understand that it can happen every now and then, but why do I see the error every single time I run the script? How often do reorgs happen?

MicahZoltu commented 6 years ago

Reorgs happen every couple minutes on main net. When they happen, if we fetch the logs after the reorg but before we have noticed the reorg then this issue you see is triggered. It is all luck of timing whether the reorg happens between the block fetch and the logs fetch.

epheph commented 6 years ago

I think it's more about infura than it is about mainnet, since each request gets routed to a different, independent ethereum node, so one node would tell you that block height X, 0xABC is ready, while you hit a different node on the follow-up request for logs of block height X.

MicahZoltu commented 6 years ago

Fixed in #18.

MicahZoltu commented 6 years ago

Fix released in v5.0.0.

mohoff commented 6 years ago

Thanks @MicahZoltu , this error is gone after I provided a onError handler in the 0x code. However, there's a new one now, which seems related:

Error: Received log for block hash 0x7adf6266c6816b44460fa4f518d1c8882ff41ad2880f1978015d7170cd366e95 when asking for logs of block 0x603d6e5b202e264768bf0e1394b55504aa05e0b5f45a1b8aebf71cc905731c25.
    at /home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:154:19
    at Array.forEach (<anonymous>)
    at ensureBlockhash (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:152:10)
    at Object.<anonymous> (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:52:21)
    at step (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:32:23)
    at Object.next (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:13:53)
    at fulfilled (/home/mo/dev/0x-openrelay-playground/node_modules/0x.js/node_modules/ethereumjs-blockstream/output/source/log-reconciler.js:4:58)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:188:7)
MicahZoltu commented 6 years ago

The error is informative, not fatal, as of v5.0.0. It means that you received something unexpected from the remote host, but blockstream will now recover when you provide it the next block. Previously the error was fatal.

mohoff commented 6 years ago

Thanks @MicahZoltu , it works now!