Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Index -1 out of bounds for length 0 #900

Closed
letypequividelespoubelles opened this issue Jul 30, 2024 · 24 comments
Closed

Index -1 out of bounds for length 0 #900

letypequividelespoubelles opened this issue Jul 30, 2024 · 24 comments
Labels
bug Something isn't working ranges

Comments

@letypequividelespoubelles
Copy link
Collaborator

letypequividelespoubelles commented Jul 30, 2024

Ranges

Spotted by @gusiri

2250131-2250478
@letypequividelespoubelles letypequividelespoubelles added the bug Something isn't working label Jul 30, 2024
@letypequividelespoubelles
Copy link
Collaborator Author

seems same issue as #877

@FlorianHuc
Copy link
Collaborator

this error happens on 2250385

This block has a single tx and the zktracer finds this error when checking the sender:

ValidationResult{invalidReason=Optional[UPFRONT_COST_EXCEEDS_BALANCE], errorMessage=Optional[transaction up-front cost 0xb6447b9791cb93 exceeds transaction sender account balance 0xe3b390101c37c]}

Because of this, the tx is not traced, and given it's the only transaction, the tracer creates a BlockSnapshot with no tx. And then it leads to the out of bound exception.

@FlorianHuc
Copy link
Collaborator

when getting the conflated trace from block 2250131 to block 2250478,

The sender balance of 0x6186bff11ac9acc75724b3c11f7ac0c13de7f3bd is set as 0x000000000000000000000000000000000000000000000000000e3b390101c37c before the tx of the above block is executed.

If we retrieve the conflated trace for block 2250385 alone, then it is 0x00000000000000000000000000000000000000000000000000b6475b85e1edc7 and it's enough for the upfront cost, hence the tx passes.

This means that while the conflated trace from 2250131 to 2250385, the balance of the sender is not computed properly.

@FlorianHuc
Copy link
Collaborator

we can reproduce the error with the smaller range
2250350 -> 2250385

the error is most likely while evaluating tx: https://lineascan.build/tx/0x5cc8d84bd0d5be9e84eb857c3a571293b202f4e2c5e6b046e6f857bc9958ab38

@letypequividelespoubelles
Copy link
Collaborator Author

@FlorianHuc
Copy link
Collaborator

For some reason, the MainnetTransactionProcessor computes a balance of 0x000000000000000000000000000000000000000000000000000e3b390101c37c post the transaction and the refund, but when we retrieve the balance through rpc call we get a different value:

curl -X POST --data '{"jsonrpc":"2.0","method":"eth_getBalance","params":["0x6186bff11ac9acc75724b3c11f7ac0c13de7f3bd", "2250351"],"id":53}' http://127.0.0.1:15480
{"jsonrpc":"2.0","id":53,"result":"0xb6475b85e1edc7"}

I stop investigating here as i don't know what more to look at.

@gusiri
Copy link
Contributor

gusiri commented Aug 21, 2024

@FlorianHuc
with tracer v0.4.0-rc1 now we get

time curl --location --request POST 'http://127.0.0.1:15480' --header 'Content-Type: application/json' --data-raw '{"jsonrpc": "2.0","method": "linea_generateConflatedTracesToFileV2","params": [{"startBlockNumber": 2250131,"endBlockNumber": 2250478,"expectedTracesEngineVersion": "0.4.0-rc1"}],"id": 1}'

{"jsonrpc":"2.0","id":1,"error":{"code":-32603,"message":"Plugin internal error","data":"relBlock has invalid value (256)

@gusiri
Copy link
Contributor

gusiri commented Aug 27, 2024

with tracer v0.5.0-beta now we get this error message below.
Use 2250197-2250197 for debugging.

time curl --location --request POST 'http://localhost:15480' --header 'Content-Type: application/json' --data-raw '{"jsonrpc": "2.0","method": "linea_generateConflatedTracesToFileV2","params": [{"startBlockNumber": 2250197,"endBlockNumber": 2250197,"expectedTracesEngineVersion": "v0.5.0-beta"}],"id": 1}'



{"jsonrpc":"2.0","id":1,"error":{"code":-32603,"message":"Plugin internal error","data":"Exceptions triggered while tracing:\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n  - null\n"}}
06:57:18.712 [vert.x-worker-thread-7] ERROR org.hyperledger.besu.ethereum.api.query.BlockchainQueries - failed worldstate query for 0x763730df5c43979c6dd19f1da750482a303b45c87c4448b2d4a50222a1ff84ae
net.consensys.linea.zktracer.ZkTracer$TracingExceptions: Exceptions triggered while tracing:
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null

        at net.consensys.linea.zktracer.ZkTracer.traceEndConflation(ZkTracer.java:184) ~[?:?]
        at org.hyperledger.besu.services.TraceServiceImpl.lambda$trace$3(TraceServiceImpl.java:166) ~[besu-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.Tracer.lambda$processTracing$0(Tracer.java:51) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.query.BlockchainQueries.lambda$getAndMapWorldState$24(BlockchainQueries.java:950) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at java.base/java.util.Optional.flatMap(Optional.java:289) ~[?:?]
        at org.hyperledger.besu.ethereum.api.query.BlockchainQueries.getAndMapWorldState(BlockchainQueries.java:946) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.Tracer.lambda$processTracing$1(Tracer.java:49) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at java.base/java.util.Optional.flatMap(Optional.java:289) ~[?:?]
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.Tracer.processTracing(Tracer.java:47) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.Tracer.processTracing(Tracer.java:37) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.services.TraceServiceImpl.trace(TraceServiceImpl.java:154) ~[besu-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at net.consensys.linea.plugins.rpc.tracegeneration.GenerateConflatedTracesV2.execute(GenerateConflatedTracesV2.java:87) ~[?:?]
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.PluginJsonRpcMethod.response(PluginJsonRpcMethod.java:50) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.jsonrpc.execution.BaseJsonRpcProcessor.process(BaseJsonRpcProcessor.java:44) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.jsonrpc.execution.TracedJsonRpcProcessor.process(TracedJsonRpcProcessor.java:54) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.jsonrpc.execution.TimedJsonRpcProcessor.process(TimedJsonRpcProcessor.java:45) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.jsonrpc.execution.JsonRpcExecutor.execute(JsonRpcExecutor.java:92) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.handlers.AbstractJsonRpcExecutor.executeRequest(AbstractJsonRpcExecutor.java:87) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.handlers.JsonRpcObjectExecutor.execute(JsonRpcObjectExecutor.java:57) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$0(JsonRpcExecutorHandler.java:57) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at java.base/java.util.Optional.ifPresentOrElse(Optional.java:196) ~[?:?]
        at org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$2(JsonRpcExecutorHandler.java:54) ~[besu-api-24.8-develop-dce796c.jar:24.8-develop-dce796c]
        at io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48) ~[vertx-web-4.5.8.jar:4.5.8]
        at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:191) ~[vertx-core-4.5.8.jar:4.5.8]
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:279) ~[vertx-core-4.5.8.jar:4.5.8]
        at io.vertx.core.impl.ContextImpl.lambda$internalExecuteBlocking$2(ContextImpl.java:210) ~[vertx-core-4.5.8.jar:4.5.8]
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.110.Final.jar:4.1.110.Final]
        at java.base/java.lang.Thread.run(Thread.java:1583) [?:?]

@DavePearce
Copy link
Collaborator

DavePearce commented Aug 27, 2024

@gusiri @FlorianHuc So I can repeat what you have above and see the same failure. However, I can still get the trace for that file by using a different RPC method (following what the existing scripts/capture.pl script did). Specifically, using this script:

#!/bin/bash
START_BLOCK=$1
END_BLOCK=$2
METHOD='linea_captureConflation'
NODE='ec2-18-117-9-115.us-east-2.compute.amazonaws.com:15480'
DATA="{\"jsonrpc\": \"2.0\",\"method\": \"$METHOD\",\"params\": [$START_BLOCK,$END_BLOCK],\"id\": 1}"

echo "Fetching traces for blocks $START_BLOCK ... $END_BLOCK"
curl -X POST --data "$DATA" $NODE | jq '.result.capture' -r | jq . | gzip > $START_BLOCK-$END_BLOCK.json.gz

Note that you have to have jq installed locall (e.g. brew install jq).

I don't know why there is a difference here.

Of course, its because you are generating the actual lt file where as I'm only generating the replay file 🤦‍♂️

@DavePearce
Copy link
Collaborator

DavePearce commented Aug 27, 2024

Also, on arith-dev this replay fails (incorrectly) on this transaction:

13:29:33.721 [Test worker] DEBUG org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor -- Transaction 0xf8768ddbf6bbfe5b4aa5ec5a0515aad16b469812614f63c9ffeeaeb8ed4b6cbb reverted: 0x08c379a0000000000000000...

@gusiri
Copy link
Contributor

gusiri commented Aug 27, 2024

So... seems like

  1. get replay files from the shadow node run linea-tracer replay()
  2. get each trace from the besu node run linea-tracer conflation (generateConflatedTracesToFileV2)

are actually related and we are trying to solve the same problem.
(#877 (comment))

@DavePearce
Copy link
Collaborator

@gusiri I'm not sure I want to say they are the same issue yet. A few things:

  1. Executing the replay file leads to relBlock has invalid value (256). However, there a lot of invalid transactions beforehand (e.g. where transactions revert when they shouldn't) --- probably related to Divergent Gas Calculation for Calls in Replay Tests #953.
  2. I haven't looked at an lt file generated using the generateConflatedTracesToFileV2. What makes you think the problem is the same as above? maybe there is some bit of this puzzle I haven't seen yet?

@DavePearce
Copy link
Collaborator

Maybe the answer here is to actually look inside an lt file and see what differences there are from one generated from via a replay file?

@gusiri
Copy link
Contributor

gusiri commented Aug 27, 2024

Test 2 only runs conflation-related methods, and Test 1 also runs conflation after replay(). So, I assumed Test 2 was a subset of Test 1? I know we have different issues in replay(), which might be preventing us from observing these errors in the conflation-related methods.

@gusiri
Copy link
Contributor

gusiri commented Aug 27, 2024

Also, the latest arith-dev (v0.5.0-beta) resolved some issues (or at least changes error messages): #898.

Is this because we touched Hub in v0.5.0-beta and it affects the way we call hub.traceEndConflation(state)?

ZkTracer.java
 @Override
  public void traceEndConflation(final WorldView state) {
    try {
      this.hub.traceEndConflation(state);
      this.pin55.ifPresent(Pin55::traceEndConflation);
    } catch (final Exception e) {
      this.tracingExceptions.add(e);
    }

    if (!this.tracingExceptions.isEmpty()) {
      throw new TracingExceptions(this.tracingExceptions);
    }
  }

@gusiri
Copy link
Contributor

gusiri commented Aug 27, 2024

Trying to get the lt file.
@FlorianHuc I can't get the lt file for 2250197-2250197 because the conflation RPC failed for this block.
Is there a way to get 2250197-2250197.lt out of besu/traces ? I see only *-SNAPSHOT.traces.lt.
We are trying to compare 2250197-2250197.lt from besu and from replay()

@gusiri
Copy link
Contributor

gusiri commented Aug 27, 2024

@DavePearce @FlorianHuc Just checked that this error in 2250197-2250197 has been fixed by the very latest arith-dev.
#900 (comment)


With the full original range 2250131-2250478, now we have this error (related: #899)

{"jsonrpc":"2.0","id":1,"error":{"code":-32603,"message":"Plugin internal error","data":"relBlock has invalid value (256)"}}

Let me narrow down the block range.

@DavePearce
Copy link
Collaborator

DavePearce commented Aug 27, 2024

@gusiri Ok, so here's a test which shows the replay test mechanism is definitely broken, and that the traces coming from the BESU node better reflect mainnet:

  1. I focused on block 6110043 which has three successful transactions.
  2. I obtained the replay file from the shadow node. This shows tx 0x4ca3bfcb7db8cffd4c06c8247cb612cfecba3491fd6c116d988c4502620242b3 failing due to INSUFFICIENT_GAS
  3. I obtained the lt file from the BESU node using method linea_generateConflatedTracesToFileV2. Looking through this file, I see the following entries for the column txndata.STATUS_CODE:
txndata.STATUS_CODE |  1 |  1 |  1 |  1 |  1 |  1 |  1 |  1 |  1 |  1 |   1 |   1 |   1 |   1 |   1 |   1 |   1 |   1 |   1 |   1 |   1 |   1 |   1 |   1 |   1 |

This is showing that all transactions succeed --- unlike for the replay test where one of them fails. I also confirmed that there are exactly three transactions in the trace.

Also, the replay files from the BESU node versus the shadow node are showing the same problems with unexpectedly reverting transactions.

@gusiri
Copy link
Contributor

gusiri commented Aug 27, 2024

@DavePearce Thank you for the debugging and comparison, David. It was really informative. Things are now clearer than before.

@gusiri
Copy link
Contributor

gusiri commented Aug 27, 2024

We And I also found something interesting here.

Current status:

full range: 2250131-2250478:


{"jsonrpc":"2.0","id":1,"error":{"code":-32603,"message":"Plugin internal error","data":"relBlock has invalid value (256)"}}
real	2m34.476s
user	0m0.012s
sys	0m0.000s

When I divided the range into smaller ranges:

range 1: 2250131-2250241: Success
range 2: 2250242-2250478: Success

So, the range is a bit larger than what can be configured in Besu or ZkTracer, I guess?
maybe (256) means the max # of blocks :)

@gusiri
Copy link
Contributor

gusiri commented Aug 27, 2024

Actually it is :) @DavePearce @FlorianHuc

With 255 blocks : Success
With 256 blocks: Fail

range: 2250131-2250385 (255 blocks)

{"jsonrpc":"2.0","id":1,"result":{"tracesEngineVersion":"0.5.0-beta","conflatedTracesFileName":"/data/besu/conflated/2250131-2250385.conflated.0.5.0-beta.lt"}}
real	2m15.539s
user	0m0.000s
sys	0m0.012s

range: 2250131-2250386 (256 blocks)

{"jsonrpc":"2.0","id":1,"error":{"code":-32603,"message":"Plugin internal error","data":"relBlock has invalid value (256)"}}

@gusiri
Copy link
Contributor

gusiri commented Aug 27, 2024

conflation 2250131-2250478 now has #899

@gusiri gusiri closed this as completed Aug 27, 2024
@DavePearce
Copy link
Collaborator

@gusiri And now we come full circle. So, having identified another bug (#998) and fixing it temporarily on my branch, then executing the replay 2250197-2250197.json.gz I get this output:

Exceptions triggered while tracing:
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null
  - null


java.lang.IllegalArgumentException
	at com.google.common.base.Preconditions.checkArgument(Preconditions.java:129)
	at net.consensys.linea.zktracer.module.romlex.RomLex.resolvePostExecution(RomLex.java:243)

That looks kinda familiar. So I must be on the right track now :)

@gusiri
Copy link
Contributor

gusiri commented Aug 28, 2024

@DavePearce It really is a full circle :) It's a 'welcome' error message. Looks good!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working ranges
Projects
None yet
Development

No branches or pull requests

5 participants