panic in backend executing request

maoueh commented 1 year ago

[2023-08-30 16:38:18.537 EDT] INFO (substreams-tier1.tier1) substreams request stats {
  "api_key_id": "045169e569e1c080cb3984b58e11014efae570e10a5e1571378cdcda57e03ff6",
  "block_count": 0,
  "block_rate_per_sec": "0.000",
  "module_exec_duration": 0,
  "output_module_hash": "eaf2fc2ea827d6aca3d5fee4ec9af202f3d1b725",
  "output_module_name": "db_out",
  "parallel_duration": 0,
  "production_mode": true,
  "tier": "tier1",
  "trace_id": "996498a15439fdbef5f27232104f86cc",
  "user_id": "0bevuabef54becd7741bf"
}
[2023-08-30 16:38:18.538 EDT] ERROR (substreams-tier1) http2: panic serving 35.191.26.158:51445: runtime error: invalid memory address or nil pointer dereference
goroutine 228100 [running]:
net/http.(*http2serverConn).runHandler.func1()
    /opt/hostedtoolcache/go/1.20.7/x64/src/net/http/h2_bundle.go:6042 +0x145
panic({0x25c22a0, 0x508a580})
    /opt/hostedtoolcache/go/1.20.7/x64/src/runtime/panic.go:884 +0x213
github.com/streamingfast/substreams/orchestrator/plan.BuildTier1RequestPlan(0x1, 0x3e8, 0xaea9ef, 0xb6f3f1, 0xaf04b0, 0xaf04b0, 0x0)
    /home/runner/go/pkg/mod/github.com/streamingfast/substreams@v1.1.11/orchestrator/plan/requestplan.go:86 +0x285
github.com/streamingfast/substreams/service.(*Tier1Service).blocks(0xc0005d85a0, {0x354a9a8, 0xc170a9abe0}, 0xc0172ca800, 0xc0164259e0, 0xc0421b8cb0)
    /home/runner/go/pkg/mod/github.com/streamingfast/substreams@v1.1.11/service/tier1.go:400 +0x133d
github.com/streamingfast/substreams/service.(*Tier1Service).Blocks(0xc0005d85a0, {0x354aa50, 0xc025033c50}, 0xc0421b8a80, 0x1?)
    /home/runner/go/pkg/mod/github.com/streamingfast/substreams@v1.1.11/service/tier1.go:235 +0x16a5
github.com/bufbuild/connect-go.NewServerStreamHandler[...].func1({0x3551cf0, 0xc0ca1fc8e0})
    /home/runner/go/pkg/mod/github.com/bufbuild/connect-go@v1.8.0/handler.go:142 +0x2e2
github.com/streamingfast/dgrpc/server/connect-web.ContentTypeInterceptor.WrapStreamingHandler.func1({0x354aa50, 0xc025033c50}, {0x3551cf0?, 0xc0ca1fc8e0?})
    /home/runner/go/pkg/mod/github.com/streamingfast/dgrpc@v0.0.0-20230623191332-4ed02c06bc6f/server/connect-web/server.go:238 +0x8d
github.com/streamingfast/dauth/middleware/connect.(*AuthInterceptor).WrapStreamingHandler.func1({0x354aa50, 0xc02b07e330}, {0x3551cf0?, 0xc0ca1fc8e0?})
    /home/runner/go/pkg/mod/github.com/streamingfast/dauth@v0.0.0-20230726175303-fc1d7198cb33/middleware/connect/middleware.go:57 +0x1e2
github.com/streamingfast/dgrpc/server/tracelog.LoggingInterceptor.WrapStreamingHandler.func1({0x354aa50?, 0xc02b07e270?}, {0x3551cf0, 0xc0ca1fc8e0})
    /home/runner/go/pkg/mod/github.com/streamingfast/dgrpc@v0.0.0-20230623191332-4ed02c06bc6f/server/tracelog/tracelog.go:74 +0x51
github.com/bufbuild/connect-opentelemetry-go.(*Interceptor).WrapStreamingHandler.func1({0x354a9a8, 0xc13f615f40}, {0x7efc9c3fe1f8, 0xc0ca1fc880})
    /home/runner/go/pkg/mod/github.com/bufbuild/connect-opentelemetry-go@v0.3.0/interceptor.go:314 +0xcb6
github.com/bufbuild/connect-go.(*Handler).ServeHTTP(0xc00018b500, {0x3548e70, 0xc026e9ea28}, 0xc1443faf00)
    /home/runner/go/pkg/mod/github.com/bufbuild/connect-go@v1.8.0/handler.go:244 +0x7db
net/http.(*ServeMux).ServeHTTP(0x1000?, {0x3548e70, 0xc026e9ea28}, 0xc1443faf00)
    /opt/hostedtoolcache/go/1.20.7/x64/src/net/http/server.go:2500 +0x149
net/http.(*ServeMux).ServeHTTP(0xc0000012c0?, {0x3548e70, 0xc026e9ea28}, 0xc1443faf00)
    /opt/hostedtoolcache/go/1.20.7/x64/src/net/http/server.go:2500 +0x149
github.com/rs/cors.(*Cors).Handler.func1({0x3548e70, 0xc026e9ea28}, 0xc1443faf00)
    /home/runner/go/pkg/mod/github.com/rs/cors@v1.8.3/cors.go:236 +0x1c4
net/http.HandlerFunc.ServeHTTP(0x0?, {0x3548e70?, 0xc026e9ea28?}, 0x1000?)
    /opt/hostedtoolcache/go/1.20.7/x64/src/net/http/server.go:2122 +0x2f
golang.org/x/net/http2/h2c.h2cHandler.ServeHTTP({{0x3531760?, 0xc002718760?}, 0xc0032ca370?}, {0x3548e70, 0xc026e9ea28}, 0xc1443faf00)
    /home/runner/go/pkg/mod/golang.org/x/net@v0.10.0/http2/h2c/h2c.go:125 +0x59b
net/http.serverHandler.ServeHTTP({0x973da7?}, {0x3548e70, 0xc026e9ea28}, 0xc1443faf00)
    /opt/hostedtoolcache/go/1.20.7/x64/src/net/http/server.go:2936 +0x316
net/http.initALPNRequest.ServeHTTP({{0x354aa50?, 0xc0db4699b0?}, 0xc01a3d6700?, {0xc0001fc3c0?}}, {0x3548e70, 0xc026e9ea28}, 0xc1443faf00)
    /opt/hostedtoolcache/go/1.20.7/x64/src/net/http/server.go:3545 +0x245
net/http.(*http2serverConn).runHandler(0xc03319bfd0?, 0x9731ea?, 0x0?, 0x0?)
    /opt/hostedtoolcache/go/1.20.7/x64/src/net/http/h2_bundle.go:6049 +0x83
created by net/http.(*http2serverConn).processHeaders
    /opt/hostedtoolcache/go/1.20.7/x64/src/net/http/h2_bundle.go:5762 +0x68a
[2023-08-30 16:38:19.325 EDT] INFO (substreams-tier1.tier1) incoming Substreams Blocks request {
  "cursor": "_JJg4eDnTapu1Pl-P96aiKWwLpc_DFtuXALlKhFBj973o3DH2MzyBWJ8a0iBxKui3Ry9Hwv53NnNE3h8ppZWuNfql-ox6HRsFygkwt3p-7ztffOhMFgecL03We2KNInRWj3eawr7erEKtdS0OPHcNhY3Yc4leTfnjW1Qq9MAIfYTv3MyxTupJcnW1vvCo9dEqrZ0F-zwwSyjDzd4LBxTb8mDYaeZuDh2NA==",
  "ip_address": "76.65.85.30",
  "key_id": "045169e569e1c080cb3984b58e11014efae570e10a5e1571378cdcda57e03ff6",
  "modules": [
    "db_out",
    "graph_out"
  ],
  "output_module": "db_out",
  "production_mode": true,
  "start_block": 11446767,
  "stop_block": 11470000,
  "trace_id": "718c2eecb8df59b26885dd4b123ca327",
  "user_id": "0bevuabef54becd7741bf"
}
[2023-08-30 16:38:19.348 EDT] INFO (wasm-runtime) using default wasm runtime {"runtime":"wazero"}

Reproducible with:

substreams run -e mainnet.eth.streamingfast.io:443 https://github.com/streamingfast/substreams-eth-reth-benchmark/raw/master/reth-erc20-rocket-v1.0.6.spkg db_out -t +10 --production-mode --cursor="_JJg4eDnTapu1Pl-P96aiKWwLpc_DFtuXALlKhFBj973o3DH2MzyBWJ8a0iBxKui3Ry9Hwv53NnNE3h8ppZWuNfql-ox6HRsFygkwt3p-7ztffOhMFgecL03We2KNInRWj3eawr7erEKtdS0OPHcNhY3Yc4leTfnjW1Qq9MAIfYTv3MyxTupJcnW1vvCo9dEqrZ0F-zwwSyjDzd4LBxTb8mDYaeZuDh2NA=="

sduchesneau commented 1 year ago

Problem happens when we use a stop-block that is below the cursor's block the -t +10 flag in the cli does 'startBlock +10' instead of {either bailing out because you shouldn't use relative stop-blocks with a cursor, or doing a naïve but better 'cursor block + 11'}

of course, the server should validate that the stop-block is ABOVE the resolved start-block instead of panicking in the orchestrator's plan

colindickson commented 1 year ago

solution:

no longer support a relative stop block and cursor in the same request

code in the PR https://github.com/streamingfast/substreams/pull/289

streamingfast / substreams

panic in backend executing request #288