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

beacon panic: close of closed channel #2052

Open
gregbostrom opened this issue Sep 15, 2020 · 2 comments
Open

beacon panic: close of closed channel #2052

gregbostrom opened this issue Sep 15, 2020 · 2 comments
Assignees

Comments

@gregbostrom
Copy link

keepnetwork/keep-client:v1.3.0-rc.4

2020-09-15T01:52:28.992Z	DEBUG	keep-ethutil	packing parameters for method [relayEntry] with ABI [function relayEntry(bytes _groupSignature) returns()]: [[[24 185 223 129 138 59 78 0 133 201 192 182 195 6 131 29 74 163 249 19 147 19 99 100 66 25 131 23 123 111 49 30 1 232 18 78 112 67 85 205 247 238 7 161 152 56 225 2 190 173 14 35 68 162 200 32 250 143 159 221 124 224 210 136]]]
2020-09-15T01:52:28.992Z	DEBUG	keep-ethutil	resolving error for contract call [{From:[255 14 46 209 160 126 80 65 192 240 212 18 200 96 238 195 171 167 244 189] To:[200 51 122 148 165 13 22 25 21 19 222 244 209 230 26 104 134 191 65 15] Gas:0 GasPrice:<nil> Value:<nil> Data:[172 55 79 75 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 32 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 64 24 185 223 129 138 59 78 0 133 201 192 182 195 6 131 29 74 163 249 19 147 19 99 100 66 25 131 23 123 111 49 30 1 232 18 78 112 67 85 205 247 238 7 161 152 56 225 2 190 173 14 35 68 162 200 32 250 143 159 221 124 224 210 136]}]
2020-09-15T01:52:29.099Z	INFO	keep-relay	relay entry was submitted by the selected group on time at block [8687543]
panic: close of closed channel

goroutine 12138811 [running]:
github.com/keep-network/keep-core/pkg/chain/ethereum.(*ethereumChain).SubmitRelayEntry(0xc000168180, 0xc00f2657c0, 0x40, 0x40, 0xc004fabb08)
	/go/src/github.com/keep-network/keep-core/pkg/chain/ethereum/ethereum.go:203 +0x309
github.com/keep-network/keep-core/pkg/beacon/relay/entry.(*relayEntrySubmitter).submitRelayEntry(0xc00ed87860, 0xc00f2657c0, 0x40, 0x40, 0xc00f075f80, 0x80, 0x80, 0x848fb1, 0xc00f01e5a0, 0xc00f01e6c0, ...)
	/go/src/github.com/keep-network/keep-core/pkg/beacon/relay/entry/submission.go:62 +0x628
github.com/keep-network/keep-core/pkg/beacon/relay/entry.SignAndSubmit(0x1470840, 0xc0000ce6c0, 0x1473700, 0xc0070c6360, 0x1485cc0, 0xc000168180, 0xc000511820, 0x40, 0xe0, 0x21, ...)
	/go/src/github.com/keep-network/keep-core/pkg/beacon/relay/entry/entry.go:150 +0xbae
github.com/keep-network/keep-core/pkg/beacon/relay.(*Node).GenerateRelayEntry.func1(0xc008e18000, 0x1473700, 0xc0070c6360, 0x1485cc0, 0xc000168180, 0xc000511820, 0x40, 0xe0, 0x848fb1, 0xc001449150, ...)
	/go/src/github.com/keep-network/keep-core/pkg/beacon/relay/relay.go:136 +0xd2
created by github.com/keep-network/keep-core/pkg/beacon/relay.(*Node).GenerateRelayEntry
	/go/src/github.com/keep-network/keep-core/pkg/beacon/relay/relay.go:135 +0x328

And here is a bit bigger log snippet.

2020-09-15T01:52:23.428Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:23.428Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:23.428Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:23.428Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:23.429Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:23.430Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:23.508Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:23.508Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:25.250Z	DEBUG	addrutil	ResolveUnspecifiedAddresses:[/p2p-circuit /ip4/127.0.0.1/tcp/3919 /ip4/172.17.0.2/tcp/3919] [/ip4/172.17.0.2 /ip4/127.0.0.1] [/p2p-circuit /ip4/127.0.0.1/tcp/3919 /ip4/172.17.0.2/tcp/3919]
2020-09-15T01:52:25.250Z	DEBUG	keep-net-libp2p	replacing default announced addresses [[/ip4/127.0.0.1/tcp/3919 /ip4/172.17.0.2/tcp/3919 /ip4/107.152.47.162/tcp/3919]] with [[/ip4/107.152.47.162/tcp/3919]]
2020-09-15T01:52:28.572Z	INFO	keep-entry	[member:2] submitting relay entry [0x18b9df818a3b4e0085c9c0b6c306831d4aa3f91393136364421983177b6f311e01e8124e704355cdf7ee07a19838e102bead0e2344a2c820fa8f9fdd7ce0d288] on behalf of group [0x2941ac361bd822bab1796f04b16c339072f529c52101cc9a174e346dfd0252a51d737dd7f22ba24379237dc70f0c3d465653cf209c0f2e61781893d2c3be22ae2453cb89bd84a5b12bbac9cff5296a8a6692557cf594d52e1c04fd3c6cf998570a7e7990339fac095a1c66063d903a5475786ba26cbe8fdeb515c584d63f735f] at block [8687543]
2020-09-15T01:52:28.592Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.593Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.598Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.598Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.657Z	ERROR	keep-chain-ethereum	failed to estimate gas [gas required exceeds allowance (7999992) or always failing transaction]
2020-09-15T01:52:28.658Z	DEBUG	keep-contract-KeepRandomBeaconOperator	submitting transaction relayEntryparams: [24 185 223 129 138 59 78 0 133 201 192 182 195 6 131 29 74 163 249 19 147 19 99 100 66 25 131 23 123 111 49 30 1 232 18 78 112 67 85 205 247 238 7 161 152 56 225 2 190 173 14 35 68 162 200 32 250 143 159 221 124 224 210 136]
2020-09-15T01:52:28.686Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.686Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.726Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.726Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.748Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.748Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.761Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.761Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.762Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.763Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.811Z	DEBUG	keep-chain-ethereum	received gas price suggestion: [5000000000]
2020-09-15T01:52:28.956Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.956Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.957Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.957Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.965Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.965Z	WARN	keep-net-libp2p	message handler is too slow; dropping message
2020-09-15T01:52:28.992Z	DEBUG	keep-ethutil	packing parameters for method [relayEntry] with ABI [function relayEntry(bytes _groupSignature) returns()]: [[[24 185 223 129 138 59 78 0 133 201 192 182 195 6 131 29 74 163 249 19 147 19 99 100 66 25 131 23 123 111 49 30 1 232 18 78 112 67 85 205 247 238 7 161 152 56 225 2 190 173 14 35 68 162 200 32 250 143 159 221 124 224 210 136]]]
2020-09-15T01:52:28.992Z	DEBUG	keep-ethutil	resolving error for contract call [{From:[255 14 46 209 160 126 80 65 192 240 212 18 200 96 238 195 171 167 244 189] To:[200 51 122 148 165 13 22 25 21 19 222 244 209 230 26 104 134 191 65 15] Gas:0 GasPrice:<nil> Value:<nil> Data:[172 55 79 75 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 32 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 64 24 185 223 129 138 59 78 0 133 201 192 182 195 6 131 29 74 163 249 19 147 19 99 100 66 25 131 23 123 111 49 30 1 232 18 78 112 67 85 205 247 238 7 161 152 56 225 2 190 173 14 35 68 162 200 32 250 143 159 221 124 224 210 136]}]
2020-09-15T01:52:29.099Z	INFO	keep-relay	relay entry was submitted by the selected group on time at block [8687543]
panic: close of closed channel

goroutine 12138811 [running]:
github.com/keep-network/keep-core/pkg/chain/ethereum.(*ethereumChain).SubmitRelayEntry(0xc000168180, 0xc00f2657c0, 0x40, 0x40, 0xc004fabb08)
	/go/src/github.com/keep-network/keep-core/pkg/chain/ethereum/ethereum.go:203 +0x309
github.com/keep-network/keep-core/pkg/beacon/relay/entry.(*relayEntrySubmitter).submitRelayEntry(0xc00ed87860, 0xc00f2657c0, 0x40, 0x40, 0xc00f075f80, 0x80, 0x80, 0x848fb1, 0xc00f01e5a0, 0xc00f01e6c0, ...)
	/go/src/github.com/keep-network/keep-core/pkg/beacon/relay/entry/submission.go:62 +0x628
github.com/keep-network/keep-core/pkg/beacon/relay/entry.SignAndSubmit(0x1470840, 0xc0000ce6c0, 0x1473700, 0xc0070c6360, 0x1485cc0, 0xc000168180, 0xc000511820, 0x40, 0xe0, 0x21, ...)
	/go/src/github.com/keep-network/keep-core/pkg/beacon/relay/entry/entry.go:150 +0xbae
github.com/keep-network/keep-core/pkg/beacon/relay.(*Node).GenerateRelayEntry.func1(0xc008e18000, 0x1473700, 0xc0070c6360, 0x1485cc0, 0xc000168180, 0xc000511820, 0x40, 0xe0, 0x848fb1, 0xc001449150, ...)
	/go/src/github.com/keep-network/keep-core/pkg/beacon/relay/relay.go:136 +0xd2
created by github.com/keep-network/keep-core/pkg/beacon/relay.(*Node).GenerateRelayEntry
	/go/src/github.com/keep-network/keep-core/pkg/beacon/relay/relay.go:135 +0x328
2020-09-15T01:52:31.658Z	DEBUG	keep-block-counter	subscribing to new blocks
2020-09-15T01:52:32.465Z	INFO	keep-chain-ethereum	using [1m0s] mining check interval
2020-09-15T01:52:32.466Z	INFO	keep-chain-ethereum	using [500000000000] wei max gas price
2020-09-15T01:52:32.470Z	INFO	keep-chain-ethereum	fetching relay chain config
@gregbostrom
Copy link
Author

2minlog.txt

@pdyraga
Copy link
Member

pdyraga commented Sep 16, 2020

Thank you for submitting the issue @gregbostrom 🙌 This is indeed a problem, same as #1333, that should be solved during the work on #491.

@pdyraga pdyraga added this to the v1.3.1 milestone Sep 21, 2020
@pdyraga pdyraga self-assigned this Oct 12, 2020
nkuba added a commit to keep-network/keep-common that referenced this issue Jan 28, 2021
New Ethereum event subscription API, background event pull loop

# Overview 

There are two major changes to Ethereum subscription API proposed here:
- new subscription API with `OnEvent` and `Pipe` functions,
- background monitoring loop pulling past events from the chain.

The first change should allow implementing some handler logic easier and to avoid complex logic leading to bugs such as keep-network/keep-core#1333 or keep-network/keep-core#2052.

The second change should improve client responsiveness for operators running their nodes against Ethereum deployments that are not very reliable on the event delivery front.
  
This code has been integrated with ECDSA keep client in `keep-ecdsa` repository and can be tested there on the branch `pipe-it` (keep-network/keep-ecdsa#671).

# New API

Event subscription API has been refactored to resemble the proposition from keep-network/keep-core#491. The new event subscription mechanism allows installing event callback handler function with `OnEvent` function as well as piping events from a subscription to a channel with `Pipe` function.

Example usage of `OnEvent`:
```
handlerFn := func(
    submittingMember common.Address,
    conflictingPublicKey []byte,
    blockNumber uint64,
) {
   // (...)
}
subscription := keepContract.ConflictingPublicKeySubmitted(
	nil, // default SubscribeOpts
	nil, // no filtering on submitting member
).OnEvent(handlerFn)
```

The same subscription but with a `Pipe`:
```
sink := make(chan *abi.BondedECDSAKeepConflictingPublicKeySubmitted)

subscription := keepContract.ConflictingPublicKeySubmitted(
	nil, // default SubscribeOpts
	nil, // no filtering on submitting member
).Pipe(sink)
```

Currently, all our event subscriptions use function handlers. While it is convenient in some cases, in some other cases it is the opposite. For example, `OnBondedECDSAKeepCreated` handler in ECDSA client works perfectly fine as a function. It triggers the protocol and does not have to constantly monitor the state of the chain. On the other hand, `OnDKGResultSubmitted` handler from the beacon client needs to monitor the chain and exit the process of event publication in case another node has published the result. In this case, the code could be better structured with a channel-based subscription that would allow listening for block counter events and events from DKG result submitted subscription in one for-select loop.

# Background monitoring loop

Some nodes in the network are running against Ethereum setups that are not particularly reliable in delivering events. Events are not delivered, nodes are not starting key-generation, or are not participating in redemption signing. Another problem is the stability of the event subscription mechanism (see #62). If the web socket connection is dropped too often, the resubscription mechanism is not enough to receive events emitted when the connection was in a weird, stale state.

To address this problem, we introduce a background loop periodically pulling past events from the chain next to a regular `watchLogs` subscription. How often events are pulled and how many blocks are taken into account can be configured with `SubscribeOpts` parameters. 

This way, even if the event was lost by `watchLogs` subscription for whatever reason, it should be pulled by a background monitoring loop later. An extremely important implication of this change is that handlers should have a logic in place allowing them to de-duplicate received events even if a lot of time passed between receiving the original event and the duplicate.

I have been experimenting with various options here, including de-duplication events in the chain implementation layer, but none of them proved to be successful as the correct de-duplication algorithm requires domain knowledge about a certain type of an event and in what circumstances identical event emitted later should or should not be identified as a duplicate.

De-duplicator implementations should be added to `keep-core` and `keep-ecdsa` clients and are out of the scope of `keep-common` and this PR.
nkuba added a commit to keep-network/keep-ecdsa that referenced this issue Jan 29, 2021
Incorporating the new Ethereum event subscription API and background event pull loop

Refs #680

Depends on #663
Depends on keep-network/keep-common#63

# Overview 

There are two major changes to Ethereum subscriptions proposed here, as a result of the changes implemented in keep-network/keep-common#63:
- new subscription API with `OnEvent` and `Pipe` functions,
- background monitoring loop pulling past events from the chain.

The first change should allow implementing some handler logic easier and to avoid complex logic leading to bugs such as keep-network/keep-core#1333 or keep-network/keep-core#2052. ECDSA keep client is currently not that much affected by this chain but this may change when proper event deduplication will be implemented.

The second change should improve client responsiveness for operators running their nodes against Ethereum deployments that are not very reliable on the event delivery front. This should hopefully improve SLA of some mainnet operators of ECDSA client.


# New API

Event subscription API has been refactored in keep-network/keep-common#63 to resemble the proposition from keep-network/keep-core#491. The new event subscription mechanism allows installing event callback handler function with `OnEvent` function as well as piping events from a subscription to a channel with `Pipe` function.

Example usage of `OnEvent`:
```
handlerFn := func(
    submittingMember common.Address,
    conflictingPublicKey []byte,
    blockNumber uint64,
) {
   // (...)
}
subscription := keepContract.ConflictingPublicKeySubmitted(
	nil, // default SubscribeOpts
	nil, // no filtering on submitting member
).OnEvent(handlerFn)
```

The same subscription but with a `Pipe`:
```
sink := make(chan *abi.BondedECDSAKeepConflictingPublicKeySubmitted)

subscription := keepContract.ConflictingPublicKeySubmitted(
	nil, // default SubscribeOpts
	nil, // no filtering on submitting member
).Pipe(sink)
```

Currently, all our event subscriptions in ECDSA client use function handlers and the code has been adjusted to the new API but is still using function handlers. This may or may not change in the future depending on an individual use case.

# Background monitoring loop

Some nodes in the network are running against Ethereum setups that are not particularly reliable in delivering events. Events are not delivered, nodes are not starting key-generation, or are not participating in redemption signing. Another problem is the stability of the event subscription mechanism (see #663). If the web socket connection is dropped too often, the resubscription mechanism is not enough to receive events emitted when the connection was in a weird, stale state.

To address this problem, keep-network/keep-common#63 introduces a background loop periodically pulling past events from the chain next to a regular `watchLogs` subscription. How often events are pulled and how many blocks are taken into account can be configured with `SubscribeOpts` parameters. 

This way, even if the event was lost by `watchLogs` subscription for whatever reason, it should be pulled by a background monitoring loop later. An extremely important implication of this change is that handlers should have logic in place allowing them to de-duplicate received events even if a lot of time passed between receiving the original event and the duplicate. 

This part has been implemented in `event_deduplicator.go` for four events:
- opened keep (key generation requested),
- redemption signature requested,
- keep closed,
- keep archived.

tBTC-specific events are covered separately in #679.

The only event that is not covered with deduplication is conflicting public key submitted event but it does not look to me as something that needs to be deduplicated as the subscription is canceled immediately after this event is received.
@pdyraga pdyraga removed this from the v1.5.0 milestone Jun 2, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants