Initialize Prometheus metrics on node start where appropriate and review
the usage of the following metrics:
```
anna@kiwi:~/Documents/GitProjects/nspcc-dev/neo-go$ find | grep prometheus.go
./pkg/network/prometheus.go
./pkg/core/stateroot/prometheus.go
./pkg/core/prometheus.go
./pkg/services/rpcsrv/prometheus.go
./pkg/services/metrics/prometheus.go
```
Close#2970.
Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
Close#2894.
It should be noted that the subscriber's channel is being removed from the
list of receivers and closed, but it is still *in the list of subscribers*
and no unsubscription is performed by WSClient. Which means that RPC server
keeps sending notifications to WSClient and WSClient keeps dropping them
(because there's no receiver for this subscription and it's OK, WSClient
can handle this and this behaviour is documented). However, it's still the
caller's duty to call Unsubscribe() method for this subscription.
Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
All Notary contract witnesses in incomplete transaction (both main
and fallback) may either have invocation scripts pushing dummy signature
on stack or be empty, both ways are OK. Notary actor keeps main tx's
Notary witness empty and keeps fallback tx's Notary witness filled
with dummy signature.
Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
The reader is about to exit and it will close legacy c.Notifications, but it
will leave subscription channels at the same time. This is wrong since these
channels will no longer receive any new events, game over.
Signed-off-by: Roman Khimov <roman@nspcc.ru>
wsReader() closes c.done first and then goes over the list of
c.respChannels. Technically this means that any of the two can be taken in
this select.
Signed-off-by: Roman Khimov <roman@nspcc.ru>
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>
Move them to the core/network packages, close#2950. The name of
mempool's unsorted transactions metrics has been changed along the
way to match the core's metrics naming convention.
Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
I've carefully checked the way how new service can be added to the
Blockchain instance or to be removed from it. Current implemention
of SetNotary and SetOracle methods doesn't contain dangerous code,
and native contracts have atomic values everywhere where service
is stored.
Current implementation of Notary, Oracle and StateRoot services'
reload/disabling/enabling on SIGUSR1 is safe and doesn't require
any adjustment.
This commit closes#2944, it's not a bug in the code, it's just
stale documentation.
Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
`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>
