search

nspcc-dev / neofs-aio

NeoFS All-in-One single node deployment helper
5 stars 9 forks source link

Epochs not ticking without forcing step #54

Closed smallhive closed 1 year ago

smallhive commented 1 year ago

After new container starting, isn't possible to upload objects. Receive similar error:

init writing on API client: client failure: status: code = 1024 message = not enough nodes to SELECT from

It maybe fixed with forcing epoch creation:

make tick.epoch

Got this behaviour on the latest version 0.36.0 and 0.36.1.

Start container with:

$ docker run --env-file ./rest-gw/rest.env nspccdev/neofs-aio:0.36.0

Logs from container:

=> Try to restore blocks before running node
2023-06-07T05:40:40.613Z    INFO    initial gas supply is not set or wrong, setting default value   {"InitialGASSupply": "52000000"}
2023-06-07T05:40:40.613Z    INFO    P2PNotaryRequestPayloadPool size is not set or wrong, setting default value {"P2PNotaryRequestPayloadPoolSize": 1000}
2023-06-07T05:40:40.613Z    INFO    MaxBlockSize is not set or wrong, setting default value {"MaxBlockSize": 262144}
2023-06-07T05:40:40.613Z    INFO    MaxBlockSystemFee is not set or wrong, setting default value    {"MaxBlockSystemFee": 900000000000}
2023-06-07T05:40:40.613Z    INFO    MaxTransactionsPerBlock is not set or wrong, using default value    {"MaxTransactionsPerBlock": 512}
2023-06-07T05:40:40.613Z    INFO    TimePerBlock is not set, using deprecated SecondsPerBlock setting, consider updating your config    {"TimePerBlock": "1s"}
2023-06-07T05:40:40.613Z    INFO    MaxValidUntilBlockIncrement is not set or wrong, using default value    {"MaxValidUntilBlockIncrement": 86400}
2023-06-07T05:40:40.613Z    INFO    NativeActivations are not set, using default values
2023-06-07T05:40:40.613Z    INFO    Hardforks are not set, using default value
2023-06-07T05:40:40.615Z    INFO    no storage version found! creating genesis block
2023-06-07T05:40:40.616Z    INFO    starting service    {"service": "Prometheus", "endpoint": ":20001"}
2023-06-07T05:40:40.616Z    INFO    service hasn't started since it's disabled  {"service": "Pprof"}
2023-06-07T05:40:40.616Z    INFO    initialize restore  {"start": 0, "height": 0, "skip": 0, "count": 207}
2023-06-07T05:40:40.624Z    INFO    runtime log {"tx": "530d4655f09af64120cd73f8c64d72a76314fdddf2a7fe760dda4e3ef9b88965", "script": "f59eb74d61b1df8e1065fe011758a8c55414386d", "msg": "proxy contract initialized"}
2023-06-07T05:40:40.624Z    INFO    runtime log {"tx": "199f05b98edcc55975ceb4361e9b6337db3b1651cba997b4284929c0cde74f2f", "script": "4b3a8e1e8044affe893855c127fec3880cd5ce76", "msg": "reputation contract initialized"}
2023-06-07T05:40:40.625Z    INFO    runtime log {"tx": "91885e194037e6e565a90cc4a1dd92746b46d28afb842e30d56a16748e382e10", "script": "3dd128f6ffe307c9fcd2df21f670d39025171234", "msg": "audit contract initialized"}
2023-06-07T05:40:40.625Z    INFO    runtime log {"tx": "5b89bc7def05ed60c6a64a4162a3675512c1d3789b415f84fceb76e3886b7d59", "script": "b0aaaac052cc5860b1b79815daae87b3d8d4b849", "msg": "neofsid contract initialized"}
2023-06-07T05:40:40.626Z    INFO    runtime log {"tx": "acd42c4c1920a3b6ac74c5be628479a102104c8109bd0010248a62f7a5fcc395", "script": "95b7f52b0adde83a0955505d286421a77a168414", "msg": "balance contract initialized"}
2023-06-07T05:40:40.628Z    INFO    runtime log {"tx": "f4c9b305215fe96324f446d66cf493171fc6db298b6a1a7d5e6601b7872e3a23", "script": "707516630852f4179af43366917a36b9a78b93a5", "msg": "netmap contract initialized"}
2023-06-07T05:40:40.629Z    INFO    runtime log {"tx": "9a664a71207f2f0e525f141d71ebe2cf960dcbed54727246e50c3cfa8799517a", "script": "72576c968205e75eabc87708394839f1cf09cd57", "msg": "container contract initialized"}
2023-06-07T05:40:40.630Z    INFO    runtime log {"tx": "43affe238479f05fcbb5d88f9c62266eb3db93687ebc9752728449dc16a47a23", "script": "34269ea503e495752d62915ca0f154ba7aef92a7", "msg": "az contract initialized"}
2023-06-07T05:40:40.700Z    INFO    shutting down service   {"service": "Prometheus", "endpoint": "[::]:20001"}
2023-06-07T05:40:40.730Z    INFO    persisted to disk   {"blocks": 206, "keys": 3099, "headerHeight": 206, "blockHeight": 206, "took": "25.281578ms"}
2023-06-07T05:40:40.744Z    INFO    initial gas supply is not set or wrong, setting default value   {"InitialGASSupply": "52000000"}
2023-06-07T05:40:40.744Z    INFO    P2PNotaryRequestPayloadPool size is not set or wrong, setting default value {"P2PNotaryRequestPayloadPoolSize": 1000}
2023-06-07T05:40:40.744Z    INFO    MaxBlockSize is not set or wrong, setting default value {"MaxBlockSize": 262144}
2023-06-07T05:40:40.744Z    INFO    MaxBlockSystemFee is not set or wrong, setting default value    {"MaxBlockSystemFee": 900000000000}
2023-06-07T05:40:40.744Z    INFO    MaxTransactionsPerBlock is not set or wrong, using default value    {"MaxTransactionsPerBlock": 512}
2023-06-07T05:40:40.744Z    INFO    TimePerBlock is not set, using deprecated SecondsPerBlock setting, consider updating your config    {"TimePerBlock": "1s"}
2023-06-07T05:40:40.744Z    INFO    MaxValidUntilBlockIncrement is not set or wrong, using default value    {"MaxValidUntilBlockIncrement": 86400}
2023-06-07T05:40:40.744Z    INFO    NativeActivations are not set, using default values
2023-06-07T05:40:40.744Z    INFO    Hardforks are not set, using default value
2023-06-07T05:40:40.746Z    INFO    restoring blockchain    {"version": "0.2.8"}
2023-06-07T05:40:40.749Z    INFO    starting service    {"service": "Prometheus", "endpoint": ":20001"}
2023-06-07T05:40:40.750Z    INFO    service hasn't started since it's disabled  {"service": "Pprof"}
2023-06-07T05:40:40.750Z    INFO    ExtensiblePoolSize is not set or wrong, using default value {"ExtensiblePoolSize": 20}
2023-06-07T05:40:41.734Z    INFO    MaxWebSocketClients is not set or wrong, setting default value  {"MaxWebSocketClients": 64}
2023-06-07T05:40:41.734Z    INFO    starting rpc-server {"endpoint": ":30333"}
2023-06-07T05:40:41.734Z    INFO    node started    {"blockHeight": 206, "headerHeight": 206}
2023-06-07T05:40:41.734Z    INFO    node reached synchronized state, starting services
2023-06-07T05:40:41.734Z    INFO    starting notary service
2023-06-07T05:40:41.734Z    INFO    RPC server already started
2023-06-07T05:40:41.734Z    INFO    starting state validation service

    _   ____________        __________
   / | / / ____/ __ \      / ____/ __ \
  /  |/ / __/ / / / /_____/ / __/ / / /
 / /|  / /___/ /_/ /_____/ /_/ / /_/ /
/_/ |_/_____/\____/      \____/\____/

/NEO-GO:0.101.1/

2023-06-07T05:40:41.734Z    INFO    starting consensus service
2023-06-07T05:40:41.734Z    INFO    initializing dbft   {"height": 207, "view": 0, "index": 0, "role": "Primary"}
2023-06-07T05:40:41.734Z    INFO    sending PrepareRequest  {"height": 207, "view": 0}
2023-06-07T05:40:41.735Z    INFO    sending Commit  {"height": 207, "view": 0}
2023-06-07T05:40:41.735Z    INFO    approving block {"height": 207, "hash": "c30f5a4160e08b5209c9b011ff75568665c8299cac83d4fbe659b79cb523136b", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "4b8a82715131162f37d589fe452f24641c4d8e8e8fa41ef8487bd29e686f0e9f"}
2023-06-07T05:40:41.736Z    INFO    initializing dbft   {"height": 208, "view": 0, "index": 0, "role": "Primary"}
2023-06-07T05:40:41.764Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 207, "blockHeight": 207, "took": "14.300492ms"}
2023-06-07T05:40:42.598Z    INFO    Error encountered with rpc request  {"code": -32602, "cause": "invalid method 'GET', please retry with 'POST'", "method": "", "params": "[]"}
Changing ContainerFee configuration value to 0
2023-06-07T05:40:42.736Z    INFO    sending PrepareRequest  {"height": 208, "view": 0}
2023-06-07T05:40:42.736Z    INFO    sending Commit  {"height": 208, "view": 0}
2023-06-07T05:40:42.736Z    INFO    approving block {"height": 208, "hash": "536fcf3421f7d561894d08153c0ff9e079fcf70e0b6eb4cf3d117d8557df65bf", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "c30f5a4160e08b5209c9b011ff75568665c8299cac83d4fbe659b79cb523136b"}
2023-06-07T05:40:42.737Z    INFO    initializing dbft   {"height": 209, "view": 0, "index": 0, "role": "Primary"}
2023-06-07T05:40:42.760Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 208, "blockHeight": 208, "took": "9.330457ms"}
2023-06-07T05:40:43.232Z    INFO    runtime log {"tx": "9d685ea459c5a59b7953dd136ed93152c0d6870d25ddf645d59d8b49813101e4", "script": "707516630852f4179af43366917a36b9a78b93a5", "msg": "configuration has been updated"}
1d03dc72c811e255aede55b3bf963a1023d4f8301baebb720c5e2b8426c79b4d
Updating NeoFS epoch to 1
2023-06-07T05:40:43.737Z    INFO    sending PrepareRequest  {"height": 209, "view": 0}
2023-06-07T05:40:43.737Z    INFO    sending Commit  {"height": 209, "view": 0}
2023-06-07T05:40:43.738Z    INFO    approving block {"height": 209, "hash": "28386457de5a4f4633927f3940e896185196e7cae80c27062b46764d6f2bf46e", "tx_count": 1, "merkle": "4d9bc726842b5e0c72bbae1b30f8d423103a96bfb355deae55e211c872dc031d", "prev": "536fcf3421f7d561894d08153c0ff9e079fcf70e0b6eb4cf3d117d8557df65bf"}
2023-06-07T05:40:43.738Z    INFO    runtime log {"tx": "1d03dc72c811e255aede55b3bf963a1023d4f8301baebb720c5e2b8426c79b4d", "script": "707516630852f4179af43366917a36b9a78b93a5", "msg": "configuration has been updated"}
2023-06-07T05:40:43.738Z    INFO    initializing dbft   {"height": 210, "view": 0, "index": 0, "role": "Primary"}
2023-06-07T05:40:43.758Z    INFO    persisted to disk   {"blocks": 1, "keys": 41, "headerHeight": 209, "blockHeight": 209, "took": "7.320818ms"}
2023-06-07T05:40:43.886Z    INFO    runtime log {"tx": "ff71f40976a1291fcec5472e34420a14b24e8eebf9f027b40182944e0c2ab960", "script": "707516630852f4179af43366917a36b9a78b93a5", "msg": "process new epoch"}
e7f5af089c109aa958d4db383e8597193475f536a6ea0a832f160d29ab490ab2
Changing ContainerAliasFee configuration value to 0
2023-06-07T05:40:44.518Z    INFO    runtime log {"tx": "893146ee8ad9c0ae07f8e340c96ef8e65499023a76d3dfe1ba08d08197566b48", "script": "707516630852f4179af43366917a36b9a78b93a5", "msg": "configuration has been updated"}
e6dfcef2baad58988b6e93fb2e6c07618eb97361e93b74b6baa536193f0f2603
Updating NeoFS epoch to 1
2023-06-07T05:40:44.739Z    INFO    sending PrepareRequest  {"height": 210, "view": 0}
2023-06-07T05:40:44.739Z    INFO    sending Commit  {"height": 210, "view": 0}
2023-06-07T05:40:44.739Z    INFO    approving block {"height": 210, "hash": "4cbcd5a7b0cbcea6ee593b47d22c11ecdeb3f31600b85c4f7d95419652e59731", "tx_count": 2, "merkle": "509a8e36361b29d8f687e4eb5b69d544d12149daae21973eb59f7f3e78d75f03", "prev": "28386457de5a4f4633927f3940e896185196e7cae80c27062b46764d6f2bf46e"}
2023-06-07T05:40:44.740Z    INFO    runtime log {"tx": "e7f5af089c109aa958d4db383e8597193475f536a6ea0a832f160d29ab490ab2", "script": "707516630852f4179af43366917a36b9a78b93a5", "msg": "process new epoch"}
2023-06-07T05:40:44.740Z    INFO    runtime log {"tx": "e6dfcef2baad58988b6e93fb2e6c07618eb97361e93b74b6baa536193f0f2603", "script": "707516630852f4179af43366917a36b9a78b93a5", "msg": "configuration has been updated"}
2023-06-07T05:40:44.740Z    INFO    initializing dbft   {"height": 211, "view": 0, "index": 0, "role": "Primary"}
2023-06-07T05:40:44.764Z    INFO    persisted to disk   {"blocks": 1, "keys": 54, "headerHeight": 210, "blockHeight": 210, "took": "11.863252ms"}
Warning: FAULT VM state returned from the RPC node: at instruction 2085 (THROW): unhandled exception: "invalid epoch".
Sending transaction...
b075e36f74356dcd5cdd5603b37cdaa43612861afaf96bc17b595eb90bc39607
2023-06-07T05:40:45.181Z    info    neofs-ir/main.go:123    pprof is disabled, skip
2023-06-07T05:40:45.181Z    info    neofs-ir/main.go:123    prometheus is disabled, skip
...

Interesting may be next rows:

Updating NeoFS epoch to 1
Updating NeoFS epoch to 1
Warning: FAULT VM state returned from the RPC node: at instruction 2085 (THROW): unhandled exception: "invalid epoch".

There are few epoch updates, but then error

roman-khimov commented 1 year ago

After new container starting, isn't possible to upload objects

Do you wait for aio container started string?

The problem with 1/1/fail is that config.sh makes a tick of its own and doesn't wait for the result of it. Then blocks are naturally ticked every 240 blocks (and they're being ticked).

smallhive commented 1 year ago

Yes, aio container started I saw all times