ChainSafe / ChainSafe/gossamer

Non deterministic panic when running TestStableNetworkRPC

Open
#3,716 0 comments 0 reactions 0 assignees View on GitHub
A-debug T-bug
Dominant language
Go
Stars
454
Forks
144
PR merge metrics
No merged PRs in 30d

Description

## Describe the bug

- While fixing bug #3616 another unexpected non deterministic behaviour was found. This happens much rarely than one mentioned before but never the less this might be a symptom of something wrong.
- Message of the panic mentions issue #3066

## Expected Behavior

- Test TestStableNetworkRPC should deterministically work

## Current Behavior

- Test TestStableNetworkRPC should un deterministically fail with next error;
```=== RUN TestStableNetworkRPC
system_integration_test.go:53: Node alice-0 is ready
system_integration_test.go:53: Node bob-1 is ready
system_integration_test.go:53: Node charlie-2 is ready
system_integration_test.go:65: waiting for all nodes to be connected
system_integration_test.go:71: starting node alice-0 with port http://localhost:8540
system_integration_test.go:74: Reponse: {Peers:1 IsSyncing:false ShouldHavePeers:true}
node.go:233: node charlie-2 crashed: charlie-2 encountered a runtime error: exit status 2
command: /var/www/gossamer/bin/gossamer --base-path /var/folders/1w/hmk5hlnd4tj3hhlkm0g7kln80000gn/T/TestStableNetworkRPC1793814496/003 --chain /var/www/gossamer/chain/westend-dev/westend-dev-spec-raw.json --role full --no-telemetry

/var/folders/1w/hmk5hlnd4tj3hhlkm0g7kln80000gn/T/TestStableNetworkRPC1793814496/003

Logs:
2024-01-19T16:01:03+01:00 INFO 🕸️ initialising node with name Gossamer, id gssmr, base path /var/folders/1w/hmk5hlnd4tj3hhlkm0g7kln80000gn/T/TestStableNetworkRPC1793814496/003 and chain-spec /var/folders/1w/hmk5hlnd4tj3hhlkm0g7kln80000gn/T/TestStableNetworkRPC1793814496/003/chain-spec-raw.json... pkg=dot
2024-01-19T16:01:04+01:00 INFO block state hash genesis hash: 0x276bfa91f70859348285599321ea96afd3ae681f0be47d36196bac8075ea32e8 pkg=state
2024-01-19T16:01:04+01:00 INFO node initialised with name Gossamer, id gssmr, base path /var/folders/1w/hmk5hlnd4tj3hhlkm0g7kln80000gn/T/TestStableNetworkRPC1793814496/003, chain-spec /var/folders/1w/hmk5hlnd4tj3hhlkm0g7kln80000gn/T/TestStableNetworkRPC1793814496/003/chain-spec-raw.json, block 0 and genesis hash 0x276bfa91f70859348285599321ea96afd3ae681f0be47d36196bac8075ea32e8 pkg=dot
2024-01-19T16:01:04+01:00 INFO 🕸️ initialising node services with global configuration name Gossamer, id gssmr and base path /var/folders/1w/hmk5hlnd4tj3hhlkm0g7kln80000gn/T/TestStableNetworkRPC1793814496/003... pkg=dot
2024-01-19T16:01:04+01:00 INFO created state service with head 0x276bfa91f70859348285599321ea96afd3ae681f0be47d36196bac8075ea32e8, highest number 0 and genesis hash 0x276bfa91f70859348285599321ea96afd3ae681f0be47d36196bac8075ea32e8 pkg=state
2024-01-19T16:01:04+01:00 INFO Generating p2p identity with seed 0 and key file /var/folders/1w/hmk5hlnd4tj3hhlkm0g7kln80000gn/T/TestStableNetworkRPC1793814496/003/node.key pkg=network
2024-01-19T16:01:04+01:00 WARN Bootstrap is enabled but no bootstrap nodes are defined pkg=network
2024-01-19T16:01:06+01:00 ERROR failed to get public IP error: Results are not identical: [46.114.5.30 2a02:3037:6e0:75cc:5181:5034:6cf0:ddc7 2a02:3037:6e0:75cc:5181:5034:6cf0:ddc7 2a02:3037:6e0:75cc:5181:5034:6cf0:ddc7 46.114.5.30 2a02:3037:6e0:75cc:5181:5034:6cf0:ddc7 2a02:3037:6e0:75cc:5181:5034:6cf0:ddc7 46.114.5.30 2a02:3037:6e0:75cc:5181:5034:6cf0:ddc7 2a02:3037:6e0:75cc:5181:5034:6cf0:ddc7 46.114.5.30]
Failed to reach http://bot.whatismyipaddress.com
Failed to reach https://shtuff.it/myip/short pkg=network
2024-01-19T16:01:06+01:00 INFO creating runtime with interpreter wazero... pkg=dot
2024-01-19T16:01:07+01:00 INFO registered notifications sub-protocol /276bfa91f70859348285599321ea96afd3ae681f0be47d36196bac8075ea32e8/grandpa/1 pkg=network
2024-01-19T16:01:07+01:00 INFO creating BABE service... pkg=dot
2024-01-19T16:01:07+01:00 INFO keystore with keys [0xc000884110] pkg=dot
2024-01-19T16:01:07+01:00 INFO creating rpc service with host localhost, external=false, port 8542, modules system,author,chain,state,rpc,grandpa,offchain,childstate,syncstate,payment, ws port 8548 and ws external=true pkg=dot
2024-01-19T16:01:07+01:00 INFO starting node Gossamer... pkg=cmd
2024-01-19T16:01:07+01:00 INFO 🕸️ starting node services... pkg=dot
2024-01-19T16:01:07+01:00 INFO Starting services: [*system.Service *network.Service *digest.Handler *core.Service *grandpa.Service *sync.Service *babe.Service *rpc.HTTPServer *state.Service] pkg=dot,services
2024-01-19T16:01:07+01:00 INFO registered notifications sub-protocol /dot/block-announces/1 pkg=network
2024-01-19T16:01:07+01:00 INFO registered notifications sub-protocol /dot/transactions/1 pkg=network
2024-01-19T16:01:07+01:00 INFO Started listening on /ip4/127.0.0.1/tcp/7006/p2p/12D3KooWPoB4BZLd9NkxfhJjX6Dqu9pjZWgFj4UZiPKWR4fEgzWD pkg=network
2024-01-19T16:01:07+01:00 INFO started network service with supported protocols /ipfs/ping/1.0.0, /ipfs/id/1.0.0, /ipfs/id/push/1.0.0, /276bfa91f70859348285599321ea96afd3ae681f0be47d36196bac8075ea32e8/grandpa/1, /dot/sync/2, /dot/light/2, /dot/block-announces/1, /dot/transactions/1 pkg=network
2024-01-19T16:01:07+01:00 INFO Starting HTTP Server on host localhost and port 8542... pkg=rpc
2024-01-19T16:01:07+01:00 INFO Starting WebSocket Server on host localhost and port 8548... pkg=rpc
2024-01-19T16:01:10+01:00 WARN target=runtime::inclusion-inherent message=ParentBlockRandomness did not provide entropy ext_logging_log_version_1 pkg=runtime module=wazero
2024-01-19T16:01:10+01:00 ERROR verifying justification: voter is not in voter set: authority ID 0xd17c2d7823ebf260fd138f2d7e27d114c0145d968b5ff5006125f2414fadae69 pkg=grandpa
panic: could not find node: for block hash 0x276bfa91f70859348285599321ea96afd3ae681f0be47d36196bac8075ea32e8 see https://github.com/ChainSafe/gossamer/issues/3066

goroutine 644 [running]:
github.com/ChainSafe/gossamer/dot/state.(*BlockState).GetRuntime(0xc0018e4e70?, {0x27, 0x6b, 0xfa, 0x91, 0xf7, 0x8, 0x59, 0x34, 0x82, ...})
github.com/ChainSafe/gossamer/dot/state/block.go:904 +0xfc
github.com/ChainSafe/gossamer/dot/core.(*Service).handleBlock(0xc00090f340, 0xc001c1d520, 0xc0003cd860)
github.com/ChainSafe/gossamer/dot/core/service.go:252 +0x41f
github.com/ChainSafe/gossamer/dot/core.(*Service).HandleBlockImport(0xc00090f340, 0xc001c1d520, 0xc0003cd860?, 0x1)
github.com/ChainSafe/gossamer/dot/core/service.go:152 +0x2f
github.com/ChainSafe/gossamer/dot/sync.(*chainSync).handleBlock(0xc00043c280, 0xc001c1d520, 0x0?)
github.com/ChainSafe/gossamer/dot/sync/chain_sync.go:935 +0x3ed
github.com/ChainSafe/gossamer/dot/sync.(*chainSync).processBlockDataWithHeaderAndBody(0xc00043c280, {{0x2c, 0x9, 0xfb, 0xa0, 0x98, 0xd1, 0xd5, 0x89, 0xb2, ...}, ...}, ...)
github.com/ChainSafe/gossamer/dot/sync/chain_sync.go:866 +0x158
github.com/ChainSafe/gossamer/dot/sync.(*chainSync).processBlockData(0xc00043c280, {{0x2c, 0x9, 0xfb, 0xa0, 0x98, 0xd1, 0xd5, 0x89, 0xb2, ...}, ...}, ...)
github.com/ChainSafe/gossamer/dot/sync/chain_sync.go:826 +0x158
github.com/ChainSafe/gossamer/dot/sync.(*chainSync).handleReadyBlock(0xc00043c280, 0xc000984780, 0x37?)
github.com/ChainSafe/gossamer/dot/sync/chain_sync.go:805 +0x157
github.com/ChainSafe/gossamer/dot/sync.(*chainSync).handleWorkersResults(0xc00043c280, 0xc001c16240, 0x30?, 0x1, 0x2)
github.com/ChainSafe/gossamer/dot/sync/chain_sync.go:765 +0x685
github.com/ChainSafe/gossamer/dot/sync.(*chainSync).requestChainBlocks(0xc00043c280, 0xc001052f00, 0xf53ab329d485a099?, {0xc0001328d0, 0x26})
github.com/ChainSafe/gossamer/dot/sync/chain_sync.go:450 +0x539
github.com/ChainSafe/gossamer/dot/sync.(*chainSync).requestAnnouncedBlock(0xc00043c280, {{0xc0001328d0?, 0xf53ab329d485a099?}, 0xc001052f00?})
github.com/ChainSafe/gossamer/dot/sync/chain_sync.go:411 +0x1e5
github.com/ChainSafe/gossamer/dot/sync.(*chainSync).onBlockAnnounce(0xc00043c280, {{0xc0001328d0?, 0xf53ab329d485a099?}, 0xc001052f00?})
github.com/ChainSafe/gossamer/dot/sync/chain_sync.go:368 +0x307
github.com/ChainSafe/gossamer/dot/sync.(*Service).HandleBlockAnnounce(0xc0004982d0, {0xc0001328d0, 0x26}, 0xc001c42000)
github.com/ChainSafe/gossamer/dot/sync/syncer.go:159 +0x567
github.com/ChainSafe/gossamer/dot/network.(*Service).handleBlockAnnounceMessage(0x1016486ce?, {0xc0001328d0?, 0xc001c3fc50?}, {0x101924bf0?, 0xc001c42000?})
github.com/ChainSafe/gossamer/dot/network/block_announce.go:212 +0x44
github.com/ChainSafe/gossamer/dot/network.(*Service).RegisterNotificationsProtocol.(*Service).createNotificationsMessageHandler.func3({0x10193c200, 0xc0004c8b00}, {0x15420c9d8, 0xc001c42000})
github.com/ChainSafe/gossamer/dot/network/notifications.go:175 +0x49b
github.com/ChainSafe/gossamer/dot/network.(*Service).readStream(0xc0001ed300, {0x10193c200?, 0xc0004c8b00}, 0xc000239360, 0xc000498990, 0x5?)
github.com/ChainSafe/gossamer/dot/network/inbound.go:47 +0x51c
github.com/ChainSafe/gossamer/dot/network.(*Service).RegisterNotificationsProtocol.func1({0x10193c200, 0xc0004c8b00})
github.com/ChainSafe/gossamer/dot/network/service.go:523 +0xce
github.com/libp2p/go-libp2p/p2p/host/basic.(*BasicHost).SetStreamHandler.func1({0x0?, 0xc00047a880?}, {0x1547e9528?, 0xc0004c8b00})
github.com/libp2p/go-libp2p@v0.31.0/p2p/host/basic/basic_host.go:598 +0x3f
created by github.com/libp2p/go-libp2p/p2p/host/basic.(*BasicHost).newStreamHandler in goroutine 643
github.com/libp2p/go-libp2p@v0.31.0/p2p/host/basic/basic_host.go:440 +0x72c
system_integration_test.go:71: starting node alice-0 with port http://localhost:8540
system_integration_test.go:73:
Error Trace: /var/www/gossamer/tests/rpc/system_integration_test.go:169
/var/www/gossamer/tests/rpc/system_integration_test.go:73
/var/www/gossamer/tests/utils/retry/untilok.go:22
/var/www/gossamer/tests/rpc/system_integration_test.go:68
Error: Received unexpected error:
cannot do HTTP request: Post "http://localhost:8540": dial tcp [::1]:8540: connect: connection refused
Test: TestStableNetworkRPC
panic: test timed out after 10m0s
```

## Possible Solution

- Need to debug this more

## To Reproduce
Steps to reproduce the behaviour:
Run
1. MODE=rpc go test ./tests/rpc/system_integration_test.go -v
2. It might be necessary to run it several times since panic is non deterministic
3.

## Specification

- go version: `1.21.6 darwin/amd64`
- gossamer version: 0.8.0
- gossamer commit tag:
- gossamer commit hash:
- operating system: mac os
- additional links:

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.