If `StartWhenSynchronized` is unset in config, `node` command runs RPC
service instantly. Previously there was a ground for deadlock. Command
started RPC server synchronously. According to server implementation, it
sends all internal failures to the parameterized error channel. Deadlock
occured because main routine didn't scan the channel.
Run `rpcsrv.Server.Start` in a separate go-routine in `startServer`.
This prevents potential deadlock caused by writing into unread channel.
Fixes#2896.
Signed-off-by: Leonard Lyubich <leonard@morphbits.io>
Previously RPC server shutdown procedure listened to the execution
channel and stopped at the first element that arrived in the queue. This
could lead to the following problems:
* stopper could steal the execution result from subscriber
* stopper didn't wait for other subscription actions to complete
Add dedicated channel to `Server` for subscription routine. Close the
channel on `handleSubEvents` return and wait for signal in `Shutdown`.
Signed-off-by: Leonard Lyubich <leonard@morphbits.io>
Previously RPC server could never be shut down completely due to
some start precondition failure (in particular, inability to serve HTTP
on any configured endpoint). The problem was caused by next facts:
* start method ran subscription routine after HTTP init succeeded only
* stop method blocked waiting for the subscription routine to return
Run `handleSubEvents` routine on fresh `Start` unconditionally. With
this change, `Shutdown` method won't produce deadlock since
`handleSubEvents` closes wait channel.
Refs #2896.
Signed-off-by: Leonard Lyubich <leonard@morphbits.io>
There is an existing problem with RPC server shutdown freeze after start
failure due to some init actions (at least HTTP listen) described in
#2896.
Add dedicated unit test which checks that `Shutdown` returns within 5s
after `Start` method encounters internal problems.
Signed-off-by: Leonard Lyubich <leonard@morphbits.io>
`cache` persisting operation is concurrent with the storage modifications
made by further state reset stages. We can't allow situation when data
from the next stage are leaking into the previous stage. State reset stages
must be atomic in turms of DB persisting, thus, use another `upperCache`
MemCached store to keep them apart.
Here are the results of mainnet's BoltDB reset from 1.1M to 6K:
This patch:
```
anna@kiwi:~/Documents/GitProjects/nspcc-dev/neo-go$ ./bin/neo-go db reset -m --debug --height 600000
2023-04-11T16:15:25.783+0300 INFO MaxBlockSize is not set or wrong, setting default value {"MaxBlockSize": 262144}
2023-04-11T16:15:25.783+0300 INFO MaxBlockSystemFee is not set or wrong, setting default value {"MaxBlockSystemFee": 900000000000}
2023-04-11T16:15:25.783+0300 INFO MaxTransactionsPerBlock is not set or wrong, using default value {"MaxTransactionsPerBlock": 512}
2023-04-11T16:15:25.783+0300 INFO MaxValidUntilBlockIncrement is not set or wrong, using default value {"MaxValidUntilBlockIncrement": 5760}
2023-04-11T16:15:25.787+0300 INFO restoring blockchain {"version": "0.2.8"}
2023-04-11T16:15:25.906+0300 INFO initializing state reset {"target height": 600000}
2023-04-11T16:15:25.906+0300 DEBUG trying to reset blocks, transactions and AERs
2023-04-11T16:15:57.031+0300 INFO intermediate batch of removed blocks, transactions and AERs is collected {"batch": 1, "took": "31.125057214s"}
2023-04-11T16:16:12.644+0300 DEBUG intermediate batch of removed blocks, transactions and AERs is persisted {"batch": 1, "took": "15.613156971s", "keys": 321895}
2023-04-11T16:16:13.895+0300 INFO intermediate batch of removed blocks, transactions and AERs is collected {"batch": 2, "took": "16.663444208s"}
2023-04-11T16:16:19.784+0300 INFO last batch of removed blocks, transactions and AERs is collected {"batch": 3, "took": "5.760308543s"}
2023-04-11T16:16:19.784+0300 INFO blocks, transactions ans AERs are reset {"took": "53.878632911s"}
2023-04-11T16:16:22.870+0300 DEBUG intermediate batch of removed blocks, transactions and AERs is persisted {"batch": 2, "took": "8.974838893s", "keys": 334823}
2023-04-11T16:16:22.870+0300 DEBUG trying to reset contract storage items
2023-04-11T16:16:27.272+0300 DEBUG last batch of removed blocks, transactions and AERs is persisted {"batch": 3, "took": "7.487357441s", "keys": 208913}
2023-04-11T16:17:23.678+0300 INFO intermediate batch of contract storage items and IDs is collected {"batch": 1, "took": "1m0.80711106s"}
2023-04-11T16:18:00.769+0300 INFO intermediate batch of contract storage items and IDs is collected {"batch": 2, "took": "36.967660061s"}
2023-04-11T16:18:20.478+0300 DEBUG intermediate batch of contract storage items is persisted {"batch": 1, "took": "56.796257788s", "keys": 200000}
2023-04-11T16:18:54.115+0300 INFO intermediate batch of contract storage items and IDs is collected {"batch": 3, "took": "33.637412437s"}
2023-04-11T16:19:18.844+0300 DEBUG intermediate batch of contract storage items is persisted {"batch": 2, "took": "1m18.0737668s", "keys": 200000}
2023-04-11T16:19:27.650+0300 INFO last batch of contract storage items is collected {"batch": 4, "took": "8.806264019s"}
2023-04-11T16:19:27.650+0300 INFO contract storage items are reset {"took": "3m4.780232077s", "keys": 656944}
2023-04-11T16:20:15.660+0300 DEBUG intermediate batch of contract storage items is persisted {"batch": 3, "took": "1m21.544386403s", "keys": 200000}
2023-04-11T16:20:15.660+0300 DEBUG trying to reset headers information
2023-04-11T16:20:16.385+0300 INFO headers information is reset {"took": "725.174932ms"}
2023-04-11T16:20:19.586+0300 DEBUG last batch of contract storage items and IDs is persisted {"batch": 4, "took": "51.936278608s", "keys": 56945}
2023-04-11T16:20:19.587+0300 DEBUG trying to reset state root information and NEP transfers
2023-04-11T16:20:35.845+0300 INFO state root information and NEP transfers are reset {"took": "16.25852114s"}
2023-04-11T16:21:10.000+0300 DEBUG headers information is persisted {"took": "53.613638429s", "keys": 528438}
2023-04-11T16:21:10.003+0300 DEBUG trying to remove stale storage items
2023-04-11T16:21:18.108+0300 INFO stale storage items are reset {"took": "8.105140658s", "keys": 1350176}
2023-04-11T16:21:18.108+0300 DEBUG trying to remove state reset point
2023-04-11T16:21:18.108+0300 INFO state reset point is removed {"took": "8.554µs"}
2023-04-11T16:21:20.151+0300 DEBUG state root information and NEP transfers are persisted {"took": "44.305707049s", "keys": 602578}
2023-04-11T16:21:20.212+0300 INFO state reset point information is persisted {"took": "2.103764633s", "keys": 2}
2023-04-11T16:21:20.213+0300 INFO reset finished successfully {"took": "5m54.306861367s"}
```
The previous commit:
```
anna@kiwi:~/Documents/GitProjects/nspcc-dev/neo-go$ ./bin/neo-go db reset -m --debug --height 600000
2023-04-11T16:24:04.256+0300 INFO MaxBlockSize is not set or wrong, setting default value {"MaxBlockSize": 262144}
2023-04-11T16:24:04.256+0300 INFO MaxBlockSystemFee is not set or wrong, setting default value {"MaxBlockSystemFee": 900000000000}
2023-04-11T16:24:04.256+0300 INFO MaxTransactionsPerBlock is not set or wrong, using default value {"MaxTransactionsPerBlock": 512}
2023-04-11T16:24:04.256+0300 INFO MaxValidUntilBlockIncrement is not set or wrong, using default value {"MaxValidUntilBlockIncrement": 5760}
2023-04-11T16:24:04.261+0300 INFO restoring blockchain {"version": "0.2.8"}
2023-04-11T16:24:04.368+0300 INFO initializing state reset {"target height": 600000}
2023-04-11T16:24:04.368+0300 DEBUG trying to reset blocks, transactions and AERs
2023-04-11T16:24:30.363+0300 INFO intermediate batch of removed blocks, transactions and AERs is collected {"batch": 1, "took": "25.995261037s"}
2023-04-11T16:24:44.947+0300 DEBUG intermediate batch of removed blocks, transactions and AERs is persisted {"batch": 1, "took": "14.584447338s", "keys": 321897}
2023-04-11T16:24:45.791+0300 INFO intermediate batch of removed blocks, transactions and AERs is collected {"batch": 2, "took": "15.428492824s"}
2023-04-11T16:24:51.252+0300 INFO last batch of removed blocks, transactions and AERs is collected {"batch": 3, "took": "5.460662766s"}
2023-04-11T16:24:51.252+0300 INFO blocks, transactions ans AERs are reset {"took": "46.884558096s"}
2023-04-11T16:24:55.399+0300 DEBUG intermediate batch of removed blocks, transactions and AERs is persisted {"batch": 2, "took": "9.607820004s", "keys": 334821}
2023-04-11T16:24:55.399+0300 DEBUG trying to reset contract storage items
2023-04-11T16:24:59.981+0300 DEBUG last batch of removed blocks, transactions and AERs is persisted {"batch": 3, "took": "8.728713255s", "keys": 208913}
2023-04-11T16:25:50.827+0300 INFO intermediate batch of contract storage items and IDs is collected {"batch": 1, "took": "55.426411416s"}
2023-04-11T16:26:28.734+0300 INFO intermediate batch of contract storage items and IDs is collected {"batch": 2, "took": "37.902647706s"}
2023-04-11T16:26:53.960+0300 DEBUG intermediate batch of contract storage items is persisted {"batch": 1, "took": "1m3.129453265s", "keys": 200001}
2023-04-11T16:27:27.645+0300 INFO intermediate batch of contract storage items and IDs is collected {"batch": 3, "took": "33.685283662s"}
2023-04-11T16:27:52.173+0300 DEBUG intermediate batch of contract storage items is persisted {"batch": 2, "took": "1m23.438465575s", "keys": 199999}
2023-04-11T16:28:00.995+0300 INFO last batch of contract storage items is collected {"batch": 4, "took": "8.821990443s"}
2023-04-11T16:28:00.995+0300 INFO contract storage items are reset {"took": "3m5.595950958s", "keys": 656944}
2023-04-11T16:28:49.164+0300 DEBUG intermediate batch of contract storage items is persisted {"batch": 3, "took": "1m21.518344712s", "keys": 200000}
2023-04-11T16:28:49.164+0300 DEBUG trying to reset headers information
2023-04-11T16:28:49.936+0300 INFO headers information is reset {"took": "772.36435ms"}
2023-04-11T16:28:53.122+0300 DEBUG last batch of contract storage items and IDs is persisted {"batch": 4, "took": "52.126928092s", "keys": 56945}
2023-04-11T16:28:53.122+0300 DEBUG trying to reset state root information and NEP transfers
2023-04-11T16:29:09.332+0300 INFO state root information and NEP transfers are reset {"took": "16.20921699s"}
2023-04-11T16:29:46.264+0300 DEBUG headers information is persisted {"took": "56.326715249s", "keys": 528438}
2023-04-11T16:29:46.267+0300 DEBUG trying to remove stale storage items
2023-04-11T16:29:53.986+0300 INFO stale storage items are reset {"took": "7.718950145s", "keys": 1350176}
2023-04-11T16:29:53.986+0300 DEBUG trying to remove state reset point
2023-04-11T16:29:53.986+0300 INFO state reset point is removed {"took": "6.013µs"}
2023-04-11T16:29:55.899+0300 DEBUG state root information and NEP transfers are persisted {"took": "46.567302762s", "keys": 602578}
2023-04-11T16:29:55.929+0300 INFO state reset point information is persisted {"took": "1.942392208s", "keys": 2}
2023-04-11T16:29:55.929+0300 INFO reset finished successfully {"took": "5m51.561573137s"}
```
Master:
```
anna@kiwi:~/Documents/GitProjects/nspcc-dev/neo-go$ ./bin/neo-go db reset -m --debug --height 600000
2023-04-11T16:34:12.410+0300 INFO MaxBlockSize is not set or wrong, setting default value {"MaxBlockSize": 262144}
2023-04-11T16:34:12.410+0300 INFO MaxBlockSystemFee is not set or wrong, setting default value {"MaxBlockSystemFee": 900000000000}
2023-04-11T16:34:12.410+0300 INFO MaxTransactionsPerBlock is not set or wrong, using default value {"MaxTransactionsPerBlock": 512}
2023-04-11T16:34:12.410+0300 INFO MaxValidUntilBlockIncrement is not set or wrong, using default value {"MaxValidUntilBlockIncrement": 5760}
2023-04-11T16:34:12.413+0300 INFO restoring blockchain {"version": "0.2.8"}
2023-04-11T16:34:12.495+0300 INFO initialize state reset {"target height": 600000}
2023-04-11T16:34:12.513+0300 INFO trying to reset blocks, transactions and AERs
2023-04-11T16:35:03.582+0300 INFO intermediate batch of removed blocks, transactions and AERs is persisted {"batches persisted": 1, "took": "51.087226195s", "keys": 321895}
2023-04-11T16:35:31.302+0300 INFO intermediate batch of removed blocks, transactions and AERs is persisted {"batches persisted": 2, "took": "27.719871393s", "keys": 334823}
2023-04-11T16:35:41.309+0300 INFO last batch of removed blocks, transactions and AERs is persisted {"batches persisted": 3, "took": "10.007017388s", "keys": 208913}
2023-04-11T16:35:41.309+0300 INFO blocks, transactions ans AERs are reset {"took": "1m28.814245057s", "overall persisted keys": 865631}
2023-04-11T16:35:41.309+0300 INFO trying to reset contract storage items
2023-04-11T16:37:38.315+0300 INFO intermediate batch of contract storage items and IDs is persisted {"batch": 1, "took": "1m57.00650253s", "keys": 200000}
2023-04-11T16:39:29.704+0300 INFO intermediate batch of contract storage items and IDs is persisted {"batch": 2, "took": "1m51.385224725s", "keys": 200000}
2023-04-11T16:41:14.991+0300 INFO intermediate batch of contract storage items and IDs is persisted {"batch": 3, "took": "1m45.287483794s", "keys": 200000}
2023-04-11T16:41:31.667+0300 INFO last batch of contract storage items and IDs is persisted {"batch": 4, "took": "16.675347478s", "keys": 56945}
2023-04-11T16:41:31.667+0300 INFO contract storage items and IDs are reset {"took": "5m50.357775401s", "keys": 656944}
2023-04-11T16:41:31.667+0300 INFO trying to reset headers information
2023-04-11T16:42:16.779+0300 INFO headers information is reset {"took": "45.111354262s", "keys": 528438}
2023-04-11T16:42:16.784+0300 INFO trying to reset state root information and NEP transfers
2023-04-11T16:42:35.778+0300 INFO state root information and NEP transfers are reset {"took": "18.99373117s", "keys": 602578}
2023-04-11T16:42:35.781+0300 INFO trying to remove stale storage items
2023-04-11T16:42:43.884+0300 INFO stale storage items are reset {"took": "8.103929306s", "keys": 1350176}
2023-04-11T16:42:43.885+0300 INFO trying to remove state reset point
2023-04-11T16:42:43.926+0300 INFO stale reset point is removed {"took": "41.858883ms", "keys": 2}
2023-04-11T16:42:43.932+0300 INFO reset finished successfully {"took": "8m31.437493325s"}
```
Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
Everywhere including examples, external interop APIs, bindings generators
code and in other valuable places. A couple of `interface{}` usages are
intentionally left in the CHANGELOG.md, documentation and tests.
