search

nspcc-dev / neofs-aio

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

Cannot create object right after container start up #47

Closed mialbu closed 1 year ago

mialbu commented 1 year ago

With the latest to provide neofs-aio in one single image (commit 74b925abde8a96ea22882d73b1ad797d30d7d5fb) I've run into problems when creating an object within ~2 minutes of neofs-aio container start up (after some time passes the object creation workes as expected). I haven't run into that problem with the second to last commit (fd041257f7ab74b2e81eeb1a409ce9ce84676c13).

I start up the neofs-aio container successfully and run tick.epoch before any other code is running. While I have issues with object creation, every other interaction works just fine. This includes the following methods of the Golang client:

I am using neofs-sdk-go in a shared library. Specifically, the error appears when the ObjectWriter calls Close() here. The exact error that is returned is type *apistatus.ServerInternal with value status: code = 1024 message = not enough nodes to SELECT from.

For completeness, the container I try to store the object to has a policy with 1 replica and a backupfactor of 0. The complete container information is the following by using [neofs-api-java]():

image

Using that container for all object related integration tests I've written have worked fine with the former commit in neofs-aio and imho should not have had any affect on this issue.

Finally, the logs I get from docker logs neofs-aio:

❯ docker logs aio
=> Try to restore blocks before running node
2023-01-20T11:37:03.302Z    INFO    initial gas supply is not set or wrong, setting default value   {"InitialGASSupply": "52000000"}
2023-01-20T11:37:03.303Z    INFO    P2PNotaryRequestPayloadPool size is not set or wrong, setting default value {"P2PNotaryRequestPayloadPoolSize": 1000}
2023-01-20T11:37:03.303Z    INFO    MaxBlockSize is not set or wrong, setting default value {"MaxBlockSize": 262144}
2023-01-20T11:37:03.303Z    INFO    MaxBlockSystemFee is not set or wrong, setting default value    {"MaxBlockSystemFee": 900000000000}
2023-01-20T11:37:03.303Z    INFO    MaxTransactionsPerBlock is not set or wrong, using default value    {"MaxTransactionsPerBlock": 512}
2023-01-20T11:37:03.303Z    INFO    MaxValidUntilBlockIncrement is not set or wrong, using default value    {"MaxValidUntilBlockIncrement": 86400}
2023-01-20T11:37:03.303Z    INFO    NativeActivations are not set, using default values
2023-01-20T11:37:03.303Z    INFO    Hardforks are not set, using default value
2023-01-20T11:37:03.307Z    INFO    no storage version found! creating genesis block
2023-01-20T11:37:03.308Z    INFO    initialize restore  {"start": 0, "height": 0, "skip": 0, "count": 84}
2023-01-20T11:37:03.308Z    INFO    service is running  {"service": "Prometheus", "endpoint": ":20001"}
2023-01-20T11:37:03.308Z    INFO    service hasn't started since it's disabled  {"service": "Pprof"}
2023-01-20T11:37:03.412Z    INFO    runtime log {"tx": "9e53234d1fe8996cfbc93f8df656f21769abd11454c0f1753e68405d77fbf9b6", "script": "ee70ca2cff1073b0335c0b4062edbaa7f59ad629", "msg": "audit contract initialized"}
2023-01-20T11:37:03.416Z    INFO    runtime log {"tx": "eb157170f07ad21269ea06b57902b3ab3e8ec563ec43fb64c764ab23bf837a04", "script": "f7a77b58e2581cb3f363977295ff870e42c42555", "msg": "balance contract initialized"}
2023-01-20T11:37:03.419Z    INFO    runtime log {"tx": "b5f945bdd776d9afa5b8bfd4543b07d1ebc78116a1c1c071f1fe590ff7053ae7", "script": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "msg": "container contract initialized"}
2023-01-20T11:37:03.425Z    INFO    runtime log {"tx": "3e47fdb0bcadb60fb80b3500e81dd0a2505b9eeaed418813447873bbdaae16b7", "script": "af4681232a16511654d007ee851a799a3475b551", "msg": "neofsid contract initialized"}
2023-01-20T11:37:03.427Z    INFO    runtime log {"tx": "710a68e90da07ab98f1fd1842b6d94d88603b13906d367f772f71245cfc5c9bf", "script": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "msg": "netmap contract initialized"}
2023-01-20T11:37:03.429Z    INFO    runtime log {"tx": "9b294401c893b53965a8e45d0cb9af8243558633ca6497367d670c57b517212c", "script": "7a2b472632f30c0bd841dbe88252096f4e1eccd4", "msg": "proxy contract initialized"}
2023-01-20T11:37:03.435Z    INFO    runtime log {"tx": "fcbcf790e99522a1d214d710feecaa7d9fd2ef65a050d6751b6d35aaaaf5eebb", "script": "f567d868746cd46c2f3a2c46a9e454cd56a1be1e", "msg": "reputation contract initialized"}
2023-01-20T11:37:03.440Z    INFO    runtime log {"tx": "d392d194e44fa7dfad9d60e2c51a411f6cf5e16ff9ed3b11e1ca572b13707eaf", "script": "73cf92b4a0a52009605d19d1dbc67db05d243662", "msg": "Az contract initialized"}
2023-01-20T11:37:03.452Z    INFO    shutting down service   {"service": "Prometheus", "endpoint": ":20001"}
2023-01-20T11:37:03.485Z    INFO    persisted to disk   {"blocks": 83, "keys": 2500, "headerHeight": 83, "blockHeight": 83, "took": "23.91621ms"}
2023-01-20T11:37:03.520Z    INFO    initial gas supply is not set or wrong, setting default value   {"InitialGASSupply": "52000000"}
2023-01-20T11:37:03.520Z    INFO    P2PNotaryRequestPayloadPool size is not set or wrong, setting default value {"P2PNotaryRequestPayloadPoolSize": 1000}
2023-01-20T11:37:03.520Z    INFO    MaxBlockSize is not set or wrong, setting default value {"MaxBlockSize": 262144}
2023-01-20T11:37:03.520Z    INFO    MaxBlockSystemFee is not set or wrong, setting default value    {"MaxBlockSystemFee": 900000000000}
2023-01-20T11:37:03.520Z    INFO    MaxTransactionsPerBlock is not set or wrong, using default value    {"MaxTransactionsPerBlock": 512}
2023-01-20T11:37:03.520Z    INFO    MaxValidUntilBlockIncrement is not set or wrong, using default value    {"MaxValidUntilBlockIncrement": 86400}
2023-01-20T11:37:03.520Z    INFO    NativeActivations are not set, using default values
2023-01-20T11:37:03.520Z    INFO    Hardforks are not set, using default value
2023-01-20T11:37:03.526Z    INFO    restoring blockchain    {"version": "0.2.6"}
2023-01-20T11:37:03.530Z    INFO    ExtensiblePoolSize is not set or wrong, using default value {"ExtensiblePoolSize": 20}
2023-01-20T11:37:03.530Z    INFO    service is running  {"service": "Prometheus", "endpoint": ":20001"}
2023-01-20T11:37:03.530Z    INFO    service hasn't started since it's disabled  {"service": "Pprof"}
2023-01-20T11:37:04.321Z    INFO    starting rpc-server {"endpoint": ":30333"}
2023-01-20T11:37:04.322Z    INFO    node started    {"blockHeight": 83, "headerHeight": 83}
2023-01-20T11:37:04.322Z    INFO    node reached synchronized state, starting services
2023-01-20T11:37:04.322Z    INFO    starting state validation service
2023-01-20T11:37:04.322Z    INFO    starting consensus service
2023-01-20T11:37:04.322Z    INFO    initializing dbft   {"height": 84, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:04.322Z    INFO    sending PrepareRequest  {"height": 84, "view": 0}
2023-01-20T11:37:04.322Z    INFO    sending Commit  {"height": 84, "view": 0}
2023-01-20T11:37:04.323Z    INFO    approving block {"height": 84, "hash": "8a0f6479bd1a842b493a4e7730deb754fde89f4450a71a6842644ed7f7e45496", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "402f0a34509787fdd8bd97a4854026dcdd1e310469684176ec0783f5e889ae36"}
2023-01-20T11:37:04.323Z    INFO    initializing dbft   {"height": 85, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:04.323Z    INFO    starting notary service
2023-01-20T11:37:04.323Z    INFO    RPC server already started

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

/NEO-GO:0.99.4/

2023-01-20T11:37:04.542Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 84, "blockHeight": 84, "took": "10.945575ms"}
2023-01-20T11:37:05.279Z    INFO    Error encountered with rpc request  {"code": -32602, "cause": "invalid method 'GET', please retry with 'POST'", "method": "", "params": "[]"}
2023-01-20T11:37:05.323Z    INFO    sending PrepareRequest  {"height": 85, "view": 0}
2023-01-20T11:37:05.324Z    INFO    sending Commit  {"height": 85, "view": 0}
2023-01-20T11:37:05.324Z    INFO    approving block {"height": 85, "hash": "14cdfc8e0d630940a1bac215ec1a50f75a4a5f97010a37af214e7531ceff48f8", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "8a0f6479bd1a842b493a4e7730deb754fde89f4450a71a6842644ed7f7e45496"}
2023-01-20T11:37:05.325Z    INFO    initializing dbft   {"height": 86, "view": 0, "index": 0, "role": "Primary"}
Changing ContainerFee configuration value to 0
2023-01-20T11:37:05.535Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 85, "blockHeight": 85, "took": "2.732668ms"}
2023-01-20T11:37:05.745Z    INFO    runtime log {"tx": "831e72cb192dac5e058af4caa85708102bfcc16a32e92e86fa2d781439ddb3e1", "script": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "msg": "configuration has been updated"}
8f295232280ad323f246e5ba3f64ff987ed810a7f0ab8a4f7b728c57709b4b44
Updating NeoFS epoch to 1
2023-01-20T11:37:06.302Z    INFO    runtime log {"tx": "3c4c493318cd5c8206f93a433cff861163668d43f11ffc35a66fa02b9fa90edc", "script": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "msg": "process new epoch"}
33ac5c793443e76daeb4a4136985f96c5ccc37943e83b380543498d22df29d8e
2023-01-20T11:37:06.326Z    INFO    sending PrepareRequest  {"height": 86, "view": 0}
2023-01-20T11:37:06.326Z    INFO    sending Commit  {"height": 86, "view": 0}
2023-01-20T11:37:06.327Z    INFO    approving block {"height": 86, "hash": "b8f8861a573b8ef65060243c48f203e8d0ad69a53f37acb2c9faa92bfb818eb4", "tx_count": 2, "merkle": "e9e53bbf7663b18c9bf0e0da862c19fe8b117aed2c7a49d18588ff2e8c97ea09", "prev": "14cdfc8e0d630940a1bac215ec1a50f75a4a5f97010a37af214e7531ceff48f8"}
2023-01-20T11:37:06.327Z    INFO    runtime log {"tx": "33ac5c793443e76daeb4a4136985f96c5ccc37943e83b380543498d22df29d8e", "script": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "msg": "process new epoch"}
2023-01-20T11:37:06.328Z    INFO    runtime log {"tx": "8f295232280ad323f246e5ba3f64ff987ed810a7f0ab8a4f7b728c57709b4b44", "script": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "msg": "configuration has been updated"}
2023-01-20T11:37:06.329Z    INFO    initializing dbft   {"height": 87, "view": 0, "index": 0, "role": "Primary"}
Changing ContainerAliasFee configuration value to 0
2023-01-20T11:37:06.536Z    INFO    persisted to disk   {"blocks": 1, "keys": 55, "headerHeight": 86, "blockHeight": 86, "took": "3.276584ms"}
2023-01-20T11:37:06.829Z    INFO    runtime log {"tx": "62d9de9948344dadcfccf8b7b05b09bbb69c0718df73eafa7be3c0769423b384", "script": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "msg": "configuration has been updated"}
c531ae9393de89385ab3a452b53ffcceafc1dcfa4b90f0d60340e41a80e681e6
Updating NeoFS epoch to 2
2023-01-20T11:37:07.327Z    INFO    sending PrepareRequest  {"height": 87, "view": 0}
2023-01-20T11:37:07.328Z    INFO    sending Commit  {"height": 87, "view": 0}
2023-01-20T11:37:07.328Z    INFO    approving block {"height": 87, "hash": "d58588503ad702685ca5490aa9b694423b1757466c4dba1469386e96447d87e7", "tx_count": 2, "merkle": "aedbdb7d3a41ac3bb5167d87247f37000d94ab7706d32c7053fc1389e0f9a2e3", "prev": "b8f8861a573b8ef65060243c48f203e8d0ad69a53f37acb2c9faa92bfb818eb4"}
2023-01-20T11:37:07.329Z    WARN    contract invocation failed  {"tx": "1fbc77873b0ce9c3e808f9fd30d06e27941a8804008352cb43a5bf034c3c96e4", "block": 87, "error": "at instruction 3051 (THROW): unhandled exception: \"invalid epoch\""}
2023-01-20T11:37:07.329Z    INFO    runtime log {"tx": "c531ae9393de89385ab3a452b53ffcceafc1dcfa4b90f0d60340e41a80e681e6", "script": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "msg": "configuration has been updated"}
2023-01-20T11:37:07.329Z    INFO    initializing dbft   {"height": 88, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:07.352Z    INFO    runtime log {"tx": "8d76a02fe4617941d28bc92eb8c9e3976a051ef45cddabb5634bdb7721d5ca2d", "script": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "msg": "process new epoch"}
5359651adea872eaabc27e8406e07b8f4b5550b21806e576613250e4c52b3451
2023-01-20T11:37:07.370Z    info    neofs-ir/main.go:123    pprof is disabled, skip
2023-01-20T11:37:07.370Z    info    neofs-ir/main.go:123    prometheus is disabled, skip
2023-01-20T11:37:07.540Z    INFO    persisted to disk   {"blocks": 1, "keys": 43, "headerHeight": 87, "blockHeight": 87, "took": "5.69502ms"}
2023-01-20T11:37:07.810Z    debug   innerring/innerring.go:414  notary support  {"sidechain_enabled": true, "mainchain_enabled": false}
2023-01-20T11:37:07.824Z    debug   settlement/processor.go:66  worker pool for settlement processor successfully initialized   {"capacity": 10}
2023-01-20T11:37:07.824Z    debug   netmap/processor.go:145 netmap worker pool  {"size": 100}
2023-01-20T11:37:07.824Z    debug   event/listener.go:455   registered new event parser {"chain": "morph", "contract": "dd782a8736da57f0d356f659cf63872c5944162d", "event_type": "RemoveNode"}
2023-01-20T11:37:07.824Z    debug   event/listener.go:455   registered new event parser {"chain": "morph", "contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:07.824Z    debug   event/listener.go:492   registered new event handler    {"chain": "morph", "contract": "dd782a8736da57f0d356f659cf63872c5944162d", "event_type": "RemoveNode"}
2023-01-20T11:37:07.824Z    debug   event/listener.go:492   registered new event handler    {"chain": "morph", "contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:07.824Z    info    event/listener.go:551   registered new event parser {"chain": "morph", "mempool_type": "added", "contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "notary_type": "addPeer"}
2023-01-20T11:37:07.824Z    info    event/listener.go:551   registered new event parser {"chain": "morph", "mempool_type": "added", "contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "notary_type": "updateState"}
2023-01-20T11:37:07.824Z    info    event/listener.go:590   registered new event handler    {"chain": "morph", "mempool_type": "added", "contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "notary type": "addPeer"}
2023-01-20T11:37:07.824Z    info    event/listener.go:590   registered new event handler    {"chain": "morph", "mempool_type": "added", "contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "notary type": "updateState"}
2023-01-20T11:37:07.824Z    debug   container/processor.go:91   container worker pool   {"size": 100}
2023-01-20T11:37:07.824Z    info    event/listener.go:551   registered new event parser {"chain": "morph", "mempool_type": "added", "contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "notary_type": "put"}
2023-01-20T11:37:07.824Z    info    event/listener.go:551   registered new event parser {"chain": "morph", "mempool_type": "added", "contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "notary_type": "putNamed"}
2023-01-20T11:37:07.824Z    info    event/listener.go:551   registered new event parser {"chain": "morph", "mempool_type": "added", "contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "notary_type": "delete"}
2023-01-20T11:37:07.824Z    info    event/listener.go:551   registered new event parser {"chain": "morph", "mempool_type": "added", "contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "notary_type": "setEACL"}
2023-01-20T11:37:07.824Z    info    event/listener.go:590   registered new event handler    {"chain": "morph", "mempool_type": "added", "contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "notary type": "put"}
2023-01-20T11:37:07.824Z    info    event/listener.go:590   registered new event handler    {"chain": "morph", "mempool_type": "added", "contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "notary type": "putNamed"}
2023-01-20T11:37:07.824Z    info    event/listener.go:590   registered new event handler    {"chain": "morph", "mempool_type": "added", "contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "notary type": "delete"}
2023-01-20T11:37:07.824Z    info    event/listener.go:590   registered new event handler    {"chain": "morph", "mempool_type": "added", "contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "notary type": "setEACL"}
2023-01-20T11:37:07.824Z    debug   balance/processor.go:63 balance worker pool {"size": 100}
2023-01-20T11:37:07.825Z    debug   event/listener.go:455   registered new event parser {"chain": "morph", "contract": "f7a77b58e2581cb3f363977295ff870e42c42555", "event_type": "Lock"}
2023-01-20T11:37:07.825Z    debug   event/listener.go:492   registered new event handler    {"chain": "morph", "contract": "f7a77b58e2581cb3f363977295ff870e42c42555", "event_type": "Lock"}
2023-01-20T11:37:07.825Z    debug   alphabet/processor.go:68    alphabet worker pool    {"size": 100}
2023-01-20T11:37:07.825Z    debug   reputation/processor.go:74  reputation worker pool  {"size": 100}
2023-01-20T11:37:07.825Z    info    event/listener.go:551   registered new event parser {"chain": "morph", "mempool_type": "added", "contract": "f567d868746cd46c2f3a2c46a9e454cd56a1be1e", "notary_type": "put"}
2023-01-20T11:37:07.825Z    info    event/listener.go:590   registered new event handler    {"chain": "morph", "mempool_type": "added", "contract": "f567d868746cd46c2f3a2c46a9e454cd56a1be1e", "notary type": "put"}
2023-01-20T11:37:07.825Z    info    event/listener.go:551   registered new event parser {"chain": "morph", "mempool_type": "added", "contract": "dd782a8736da57f0d356f659cf63872c5944162d", "notary_type": "put"}
2023-01-20T11:37:07.825Z    info    event/listener.go:590   registered new event handler    {"chain": "morph", "mempool_type": "added", "contract": "dd782a8736da57f0d356f659cf63872c5944162d", "notary type": "put"}
2023-01-20T11:37:07.825Z    debug   event/listener.go:455   registered new event parser {"chain": "morph", "contract": "dd782a8736da57f0d356f659cf63872c5944162d", "event_type": "Delete"}
2023-01-20T11:37:07.825Z    debug   event/listener.go:492   registered new event handler    {"chain": "morph", "contract": "dd782a8736da57f0d356f659cf63872c5944162d", "event_type": "Delete"}
2023-01-20T11:37:07.829Z    debug   innerring/innerring.go:1066 read config from blockchain {"active": true, "alphabet": true, "epoch": 1, "precision": 12, "init_epoch_tick_delta": 237}
2023-01-20T11:37:07.834Z    debug   client/notary.go:181    notary deposit invoke   {"amount": 9569584843895, "expire_at": 628, "vub": 90, "tx_hash": "3444789a39b838901a3d040c535d9063555b442a30186ae77a09462134a7af4d"}
2023-01-20T11:37:07.834Z    info    innerring/notary.go:85  waiting to accept side notary deposit
2023-01-20T11:37:07.834Z    INFO    Error encountered with rpc request  {"code": -100, "cause": "failed to locate application log: key not found", "method": "getapplicationlog", "params": "[3444789a39b838901a3d040c535d9063555b442a30186ae77a09462134a7af4d Application]"}
2023-01-20T11:37:08.330Z    INFO    sending PrepareRequest  {"height": 88, "view": 0}
2023-01-20T11:37:08.330Z    INFO    sending Commit  {"height": 88, "view": 0}
2023-01-20T11:37:08.331Z    INFO    approving block {"height": 88, "hash": "848b542e5174191facca533a581e74271a47ee9300b28108e51fd9e8e00188b5", "tx_count": 2, "merkle": "7ca3c9c0da622363ebf7f5c7606620dc319f266fb8524187de2cc5b46f910726", "prev": "d58588503ad702685ca5490aa9b694423b1757466c4dba1469386e96447d87e7"}
2023-01-20T11:37:08.332Z    INFO    runtime log {"tx": "5359651adea872eaabc27e8406e07b8f4b5550b21806e576613250e4c52b3451", "script": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "msg": "process new epoch"}
2023-01-20T11:37:08.333Z    INFO    initializing dbft   {"height": 89, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:08.338Z    warn    innerring/state.go:131  can't invoke vote method in alphabet contract   {"alphabet_index": 0, "epoch": 1, "error": "neofs error: chain/client: contract execution finished with state FAULT; exception: at instruction 2404 (THROW): unhandled exception: \"invalid epoch\""}
2023-01-20T11:37:08.339Z    info    neofs-ir/main.go:82 application started {"version": "v0.34.0"}
2023-01-20T11:37:08.339Z    info    taskmanager/listen.go:15    process routine {"component": "Audit task manager", "queue_capacity": 100}
2023-01-20T11:37:08.540Z    INFO    persisted to disk   {"blocks": 1, "keys": 55, "headerHeight": 88, "blockHeight": 88, "took": "5.282767ms"}
2023-01-20T11:37:09.305Z    debug   metabase/control.go:25  created directory for Metabase  {"path": "/data/metabase.db"}
2023-01-20T11:37:09.307Z    debug   metabase/control.go:46  opened boltDB instance for Metabase
2023-01-20T11:37:09.308Z    debug   metabase/control.go:48  checking metabase version
2023-01-20T11:37:09.313Z    info    neofs-node/config.go:783    shard attached to engine    {"id": "F7HJwT4ZF1ctyTAs7RNxLJ"}
2023-01-20T11:37:09.314Z    info    neofs-node/main.go:76   initializing storage engine service...
2023-01-20T11:37:09.314Z    debug   blobstor/control.go:12  opening...  {"shard_id": "F7HJwT4ZF1ctyTAs7RNxLJ"}
2023-01-20T11:37:09.315Z    debug   metabase/control.go:25  created directory for Metabase  {"shard_id": "F7HJwT4ZF1ctyTAs7RNxLJ", "path": "/data/metabase.db"}
2023-01-20T11:37:09.315Z    debug   metabase/control.go:46  opened boltDB instance for Metabase {"shard_id": "F7HJwT4ZF1ctyTAs7RNxLJ"}
2023-01-20T11:37:09.315Z    debug   metabase/control.go:48  checking metabase version   {"shard_id": "F7HJwT4ZF1ctyTAs7RNxLJ"}
2023-01-20T11:37:09.315Z    debug   blobstor/control.go:32  initializing... {"shard_id": "F7HJwT4ZF1ctyTAs7RNxLJ"}
2023-01-20T11:37:09.315Z    debug   blobovniczatree/control.go:21   initializing Blobovnicza's
2023-01-20T11:37:09.316Z    debug   blobovnicza/control.go:17   creating directory for BoltDB   {"component": "Blobovnicza", "path": "/data/blob/blobovnicza/0/0", "ro": false}
2023-01-20T11:37:09.316Z    debug   blobovnicza/control.go:31   opening BoltDB  {"component": "Blobovnicza", "path": "/data/blob/blobovnicza/0/0", "permissions": "-rwxrwxrwx"}
2023-01-20T11:37:09.321Z    debug   blobovnicza/control.go:47   initializing... {"component": "Blobovnicza", "object size limit": 1048576, "storage size limit": 1073741824}
2023-01-20T11:37:09.321Z    debug   blobovnicza/control.go:62   creating bucket for size range  {"component": "Blobovnicza", "range": "[0:32768]"}
2023-01-20T11:37:09.321Z    debug   blobovnicza/control.go:62   creating bucket for size range  {"component": "Blobovnicza", "range": "[32769:65536]"}
2023-01-20T11:37:09.321Z    debug   blobovnicza/control.go:62   creating bucket for size range  {"component": "Blobovnicza", "range": "[65537:131072]"}
2023-01-20T11:37:09.321Z    debug   blobovnicza/control.go:62   creating bucket for size range  {"component": "Blobovnicza", "range": "[131073:262144]"}
2023-01-20T11:37:09.321Z    debug   blobovnicza/control.go:62   creating bucket for size range  {"component": "Blobovnicza", "range": "[262145:524288]"}
2023-01-20T11:37:09.321Z    debug   blobovnicza/control.go:62   creating bucket for size range  {"component": "Blobovnicza", "range": "[524289:1048576]"}
2023-01-20T11:37:09.327Z    debug   blobovniczatree/control.go:39   blobovnicza successfully initialized, closing...    {"id": "0/0"}
2023-01-20T11:37:09.327Z    debug   blobovnicza/control.go:89   closing BoltDB  {"component": "Blobovnicza", "path": "/data/blob/blobovnicza/0/0"}
2023-01-20T11:37:09.331Z    info    neofs-node/main.go:78   storage engine service has been successfully initialized
2023-01-20T11:37:09.331Z    info    neofs-node/main.go:76   initializing gRPC service...
2023-01-20T11:37:09.332Z    INFO    sending PrepareRequest  {"height": 89, "view": 0}
2023-01-20T11:37:09.333Z    info    neofs-node/main.go:78   gRPC service has been successfully initialized
2023-01-20T11:37:09.333Z    INFO    sending Commit  {"height": 89, "view": 0}
2023-01-20T11:37:09.333Z    info    neofs-node/main.go:76   initializing netmap service...
2023-01-20T11:37:09.333Z    INFO    approving block {"height": 89, "hash": "1113f3a7c7ec83691ff5b8b20c7261fd32ba95174c9a45c38d0dd9f02e5cbd8e", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "848b542e5174191facca533a581e74271a47ee9300b28108e51fd9e8e00188b5"}
2023-01-20T11:37:09.335Z    INFO    initializing dbft   {"height": 90, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:09.337Z    debug   innerring/innerring.go:235  new block   {"index": 89}
2023-01-20T11:37:09.357Z    debug   neofs-node/morph.go:83  notary support  {"sidechain_enabled": true}
2023-01-20T11:37:09.357Z    debug   neofs-node/morph.go:98  morph.cache_ttl fetched from network    {"value": 1}
2023-01-20T11:37:09.359Z    info    neofs-node/netmap.go:296    initial network state   {"epoch": 2, "state": "undefined"}
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:78   netmap service has been successfully initialized
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:76   initializing accounting service...
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:78   accounting service has been successfully initialized
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:76   initializing container service...
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:78   container service has been successfully initialized
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:76   initializing session service...
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:78   session service has been successfully initialized
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:76   initializing reputation service...
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:78   reputation service has been successfully initialized
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:76   initializing notification service...
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:78   notification service has been successfully initialized
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:76   initializing object service...
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:78   object service has been successfully initialized
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:76   initializing pprof service...
2023-01-20T11:37:09.359Z    info    neofs-node/pprof.go:13  pprof is disabled
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:78   pprof service has been successfully initialized
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:76   initializing prometheus service...
2023-01-20T11:37:09.359Z    info    neofs-node/metrics.go:14    prometheus is disabled
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:78   prometheus service has been successfully initialized
2023-01-20T11:37:09.359Z    info    neofs-node/main.go:76   initializing tree service...
2023-01-20T11:37:09.360Z    info    neofs-node/tree.go:39   tree service is not enabled, skip initialization
2023-01-20T11:37:09.360Z    info    neofs-node/main.go:78   tree service has been successfully initialized
2023-01-20T11:37:09.360Z    info    neofs-node/main.go:76   initializing control service...
2023-01-20T11:37:09.360Z    info    neofs-node/main.go:78   control service has been successfully initialized
2023-01-20T11:37:09.360Z    info    neofs-node/main.go:76   initializing morph notifications service...
2023-01-20T11:37:09.360Z    debug   event/listener.go:455   registered new event parser {"contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event_type": "NewEpoch"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:455   registered new event parser {"contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "event_type": "PutSuccess"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "event_type": "PutSuccess"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:455   registered new event parser {"contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "event_type": "DeleteSuccess"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "event_type": "DeleteSuccess"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:455   registered new event parser {"contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "event_type": "StartEstimation"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "event_type": "StartEstimation"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:455   registered new event parser {"contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "event_type": "StopEstimation"}
2023-01-20T11:37:09.360Z    debug   event/listener.go:492   registered new event handler    {"contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "event_type": "StopEstimation"}
2023-01-20T11:37:09.360Z    info    neofs-node/main.go:78   morph notifications service has been successfully initialized
2023-01-20T11:37:09.360Z    info    neofs-node/main.go:110  starting NATS service...
2023-01-20T11:37:09.360Z    info    neofs-node/main.go:114  NATS service started successfully
2023-01-20T11:37:09.360Z    info    neofs-node/main.go:110  starting gRPC service...
2023-01-20T11:37:09.360Z    info    neofs-node/main.go:110  starting notary service...
2023-01-20T11:37:09.361Z    info    neofs-node/grpc.go:96   start listening gRPC endpoint   {"endpoint": "[::]:8080"}
2023-01-20T11:37:09.366Z    debug   client/notary.go:181    notary deposit invoke   {"amount": 50000000000, "expire_at": 630, "vub": 92, "tx_hash": "33fc5ca79d13014cef8585fd79d6fa2e9e650f5f8bdd2c4c4286fe3b15a3feb9"}
2023-01-20T11:37:09.366Z    INFO    Error encountered with rpc request  {"code": -100, "cause": "failed to locate application log: key not found", "method": "getapplicationlog", "params": "[33fc5ca79d13014cef8585fd79d6fa2e9e650f5f8bdd2c4c4286fe3b15a3feb9 Application]"}
2023-01-20T11:37:09.540Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 89, "blockHeight": 89, "took": "3.644613ms"}
2023-01-20T11:37:10.334Z    INFO    sending PrepareRequest  {"height": 90, "view": 0}
2023-01-20T11:37:10.334Z    INFO    sending Commit  {"height": 90, "view": 0}
2023-01-20T11:37:10.335Z    INFO    approving block {"height": 90, "hash": "2d52b592230e3f65ebabc2eb38860d21dcd4d0e513f31445bbdafd3eb5d76ad4", "tx_count": 1, "merkle": "b9fea3153bfe86424c2cdd8b5f0f659e2efad679fd8585ef4c01139da75cfc33", "prev": "1113f3a7c7ec83691ff5b8b20c7261fd32ba95174c9a45c38d0dd9f02e5cbd8e"}
2023-01-20T11:37:10.335Z    INFO    initializing dbft   {"height": 91, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:10.336Z    debug   innerring/innerring.go:235  new block   {"index": 90}
2023-01-20T11:37:10.370Z    info    neofs-node/main.go:114  notary service started successfully
2023-01-20T11:37:10.370Z    info    neofs-node/config.go:869    bootstrapping with online state {"previous": "OFFLINE"}
2023-01-20T11:37:10.376Z    debug   client/notary.go:522    notary request invoked  {"method": "addPeer", "valid_until_block": 200, "fallback_valid_for": 40, "tx_hash": "500bb6b2c06a718c85c4b2ae5e601d3b905f6b49262812a84e460732f98d2076"}
2023-01-20T11:37:10.376Z    info    neofs-node/main.go:128  application started {"version": "v0.34.0"}
2023-01-20T11:37:10.377Z    info    neofs-node/main.go:110  starting control service...
2023-01-20T11:37:10.377Z    info    neofs-node/main.go:110  starting morph notification service...
2023-01-20T11:37:10.379Z    info    netmap/handlers.go:48   notification    {"type": "add peer"}
2023-01-20T11:37:10.381Z    info    netmap/process_peers.go:65  approving network map candidate {"key": "022bb4041c50d607ff871dec7e4cd7778388e0ea6849d84ccbd9aa8f32e16a8131"}
aio container started
/usr/bin/neofs-rest-gw
2023-01-20T11:37:10.390Z    debug   client/notary.go:522    notary request invoked  {"method": "addPeerIR", "valid_until_block": 200, "fallback_valid_for": 40, "tx_hash": "bed3e09c07461a0e5dfd07c3dd00f248ce6457acf067b362094c5aa61c108343"}
2023-01-20T11:37:10.410Z    info    neofs-http-gw/app.go:275    no wallet path specified, creating ephemeral key automatically for this run
2023-01-20T11:37:10.410Z    info    neofs-http-gw/app.go:158    add connection  {"address": "localhost:8080", "weight": 1, "priority": 1}
2023-01-20T11:37:10.423Z    debug   session/executor.go:31  serving request...  {"component": "SessionService", "request": "Create"}
2023-01-20T11:37:10.424Z    warn    neofs-http-gw/app.go:478    failed to reload TLS certs  {"error": "tls disabled"}
2023-01-20T11:37:10.428Z    warn    neofs-http-gw/app.go:223    metrics are disabled
2023-01-20T11:37:10.430Z    info    neofs-http-gw/app.go:332    starting application    {"app_name": "neofs-http-gw", "version": "v0.25.0"}
2023-01-20T11:37:10.430Z    info    neofs-http-gw/app.go:513    added path /upload/{cid}
2023-01-20T11:37:10.430Z    info    neofs-http-gw/app.go:516    added path /get/{cid}/{oid}
2023-01-20T11:37:10.430Z    info    neofs-http-gw/app.go:519    added path /get_by_attribute/{cid}/{attr_key}/{attr_val:*}
2023-01-20T11:37:10.431Z    info    neofs-http-gw/app.go:521    added path /zip/{cid}/{prefix}
2023-01-20T11:37:10.431Z    info    metrics/service.go:33   service hasn't started since it's disabled  {"service": "Prometheus"}
2023-01-20T11:37:10.431Z    info    metrics/service.go:33   service hasn't started since it's disabled  {"service": "Pprof"}
2023-01-20T11:37:10.431Z    info    neofs-http-gw/app.go:416    running web server  {"address": "0.0.0.0:8081"}
2023-01-20T11:37:10.540Z    INFO    persisted to disk   {"blocks": 1, "keys": 39, "headerHeight": 90, "blockHeight": 90, "took": "2.950447ms"}
2023-01-20T11:37:10.834Z    info    neofs-rest-gw/config.go:379 added connection peer   {"address": "localhost:8080", "priority": 1, "weight": 1}
2023-01-20T11:37:10.845Z    debug   session/executor.go:31  serving request...  {"component": "SessionService", "request": "Create"}
2023-01-20T11:37:10.914Z    info    metrics/service.go:33   service hasn't started since it's disabled  {"service": "Pprof"}
2023-01-20T11:37:10.914Z    info    metrics/service.go:33   service hasn't started since it's disabled  {"service": "Prometheus"}
2023/01/20 11:37:10 Serving neofs rest gw at http://[::]:8090
2023-01-20T11:37:11.335Z    INFO    sending PrepareRequest  {"height": 91, "view": 0}
2023-01-20T11:37:11.336Z    INFO    sending Commit  {"height": 91, "view": 0}
2023-01-20T11:37:11.336Z    INFO    approving block {"height": 91, "hash": "2928a5bfb2be7badcbced955ce221dc6da3ad4e75f42a0a5440b2d9beb93279b", "tx_count": 1, "merkle": "052f79c0eb9e889d1d396db5cc0beb8fca20b857376872880b7c77c84f934aba", "prev": "2d52b592230e3f65ebabc2eb38860d21dcd4d0e513f31445bbdafd3eb5d76ad4"}
2023-01-20T11:37:11.337Z    INFO    initializing dbft   {"height": 92, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:11.338Z    debug   subscriber/subscriber.go:137    new notification event from sidechain   {"name": "AddPeerSuccess"}
2023-01-20T11:37:11.338Z    debug   subscriber/subscriber.go:137    new notification event from sidechain   {"name": "AddPeerSuccess"}
2023-01-20T11:37:11.338Z    debug   event/listener.go:326   event parser not set    {"chain": "morph", "script hash LE": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event type": "AddPeerSuccess"}
2023-01-20T11:37:11.338Z    debug   neofs-node/morph.go:238 new block   {"index": 91}
2023-01-20T11:37:11.338Z    debug   event/listener.go:326   event parser not set    {"script hash LE": "0605a9623cb07b638fc6fe243bb7dc8bc50d30cd", "event type": "AddPeerSuccess"}
2023-01-20T11:37:11.339Z    debug   innerring/innerring.go:235  new block   {"index": 91}
2023-01-20T11:37:11.542Z    INFO    persisted to disk   {"blocks": 1, "keys": 37, "headerHeight": 91, "blockHeight": 91, "took": "2.739423ms"}
2023-01-20T11:37:12.342Z    INFO    sending PrepareRequest  {"height": 92, "view": 0}
2023-01-20T11:37:12.342Z    INFO    sending Commit  {"height": 92, "view": 0}
2023-01-20T11:37:12.343Z    INFO    approving block {"height": 92, "hash": "b9fbaa0e2e9263e93a637ed6e4c66be36131dd5b49b2ff5a721f7334ca5a7b2d", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "2928a5bfb2be7badcbced955ce221dc6da3ad4e75f42a0a5440b2d9beb93279b"}
2023-01-20T11:37:12.344Z    INFO    initializing dbft   {"height": 93, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:12.344Z    debug   innerring/innerring.go:235  new block   {"index": 92}
2023-01-20T11:37:12.345Z    debug   neofs-node/morph.go:238 new block   {"index": 92}
2023-01-20T11:37:12.560Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 92, "blockHeight": 92, "took": "10.188473ms"}
2023-01-20T11:37:13.343Z    INFO    sending PrepareRequest  {"height": 93, "view": 0}
2023-01-20T11:37:13.344Z    INFO    sending Commit  {"height": 93, "view": 0}
2023-01-20T11:37:13.344Z    INFO    approving block {"height": 93, "hash": "f7d392481267289d427efe96b32170e1d90f1f5ab2e11152e2285baf116298d8", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "b9fbaa0e2e9263e93a637ed6e4c66be36131dd5b49b2ff5a721f7334ca5a7b2d"}
2023-01-20T11:37:13.346Z    INFO    initializing dbft   {"height": 94, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:13.347Z    debug   neofs-node/morph.go:238 new block   {"index": 93}
2023-01-20T11:37:13.347Z    debug   innerring/innerring.go:235  new block   {"index": 93}
2023-01-20T11:37:13.567Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 93, "blockHeight": 93, "took": "9.687919ms"}
2023-01-20T11:37:14.344Z    INFO    sending PrepareRequest  {"height": 94, "view": 0}
2023-01-20T11:37:14.345Z    INFO    sending Commit  {"height": 94, "view": 0}
2023-01-20T11:37:14.345Z    INFO    approving block {"height": 94, "hash": "d4119119b023c665c04295dd114e0abf2756e66fd5d0d766ab893961eb866b2d", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "f7d392481267289d427efe96b32170e1d90f1f5ab2e11152e2285baf116298d8"}
2023-01-20T11:37:14.346Z    INFO    initializing dbft   {"height": 95, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:14.347Z    debug   innerring/innerring.go:235  new block   {"index": 94}
2023-01-20T11:37:14.347Z    debug   neofs-node/morph.go:238 new block   {"index": 94}
2023-01-20T11:37:14.563Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 94, "blockHeight": 94, "took": "4.701267ms"}
2023-01-20T11:37:15.346Z    INFO    sending PrepareRequest  {"height": 95, "view": 0}
2023-01-20T11:37:15.346Z    INFO    sending Commit  {"height": 95, "view": 0}
2023-01-20T11:37:15.347Z    INFO    approving block {"height": 95, "hash": "122ade736ad6e42e1c7afb70c797ec703cf46cec8e4e2aefbf242d9c8618f200", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "d4119119b023c665c04295dd114e0abf2756e66fd5d0d766ab893961eb866b2d"}
2023-01-20T11:37:15.348Z    INFO    initializing dbft   {"height": 96, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:15.348Z    debug   innerring/innerring.go:235  new block   {"index": 95}
2023-01-20T11:37:15.349Z    debug   neofs-node/morph.go:238 new block   {"index": 95}
2023-01-20T11:37:15.566Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 95, "blockHeight": 95, "took": "7.060374ms"}
2023-01-20T11:37:15.771Z    INFO    runtime log {"tx": "0e837b43226476d01d4cfaa0f2a2b59e17141a7ae9d67d462fc64270c4972624", "script": "f7a77b58e2581cb3f363977295ff870e42c42555", "msg": "successfully transferred assets"}
2023-01-20T11:37:15.772Z    INFO    runtime log {"tx": "0e837b43226476d01d4cfaa0f2a2b59e17141a7ae9d67d462fc64270c4972624", "script": "af4681232a16511654d007ee851a799a3475b551", "msg": "key bound to the owner"}
2023-01-20T11:37:15.772Z    INFO    runtime log {"tx": "0e837b43226476d01d4cfaa0f2a2b59e17141a7ae9d67d462fc64270c4972624", "script": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "msg": "added new container"}
2023-01-20T11:37:15.785Z    debug   client/notary.go:522    notary request invoked  {"method": "put", "valid_until_block": 200, "fallback_valid_for": 40, "tx_hash": "7e39e68f2041e951ee6767d4f71ef5ca93be0cc8d8a0a56106adefdf6653a1bf"}
2023-01-20T11:37:15.786Z    info    container/handlers.go:16    notification    {"type": "container put", "id": "2sp9MAJAmJNxS9cYoz7fuq2juDA46Y4JaHF9fXTEkQ8P"}
2023-01-20T11:37:15.797Z    debug   client/notary.go:404    notary request with prepared main TX invoked    {"fallback_valid_for": 40, "tx_hash": "1b51ddc95049401ee9d3ce62790bd5d6f20b51f9a3aa4e821abf43bbe09d4336"}
2023-01-20T11:37:16.348Z    INFO    sending PrepareRequest  {"height": 96, "view": 0}
2023-01-20T11:37:16.348Z    INFO    sending Commit  {"height": 96, "view": 0}
2023-01-20T11:37:16.349Z    INFO    approving block {"height": 96, "hash": "91ea342cf82c017c72355a5967e46ba624aefdad84b0e675e8c43ccf85482f77", "tx_count": 1, "merkle": "7acaf73a141b9ae021190381c9d7e1df96ae1de3a45ef8d3d4cc3b7bbf0b3408", "prev": "122ade736ad6e42e1c7afb70c797ec703cf46cec8e4e2aefbf242d9c8618f200"}
2023-01-20T11:37:16.351Z    INFO    runtime log {"tx": "08340bbf7b3bccd4d3f85ea4e31dae96dfe1d7c981031921e09a1b143af7ca7a", "script": "f7a77b58e2581cb3f363977295ff870e42c42555", "msg": "successfully transferred assets"}
2023-01-20T11:37:16.352Z    INFO    runtime log {"tx": "08340bbf7b3bccd4d3f85ea4e31dae96dfe1d7c981031921e09a1b143af7ca7a", "script": "af4681232a16511654d007ee851a799a3475b551", "msg": "key bound to the owner"}
2023-01-20T11:37:16.352Z    INFO    runtime log {"tx": "08340bbf7b3bccd4d3f85ea4e31dae96dfe1d7c981031921e09a1b143af7ca7a", "script": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "msg": "added new container"}
2023-01-20T11:37:16.353Z    INFO    initializing dbft   {"height": 97, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:16.355Z    debug   subscriber/subscriber.go:137    new notification event from sidechain   {"name": "PutSuccess"}
2023-01-20T11:37:16.355Z    debug   neofs-node/morph.go:238 new block   {"index": 96}
2023-01-20T11:37:16.355Z    error   neofs-node/container.go:92  read newly created container after the notification {"id": "2sp9MAJAmJNxS9cYoz7fuq2juDA46Y4JaHF9fXTEkQ8P", "error": "status: code = 3072"}
2023-01-20T11:37:16.356Z    debug   neofs-node/container.go:98  container creation event's receipt  {"id": "2sp9MAJAmJNxS9cYoz7fuq2juDA46Y4JaHF9fXTEkQ8P"}
2023-01-20T11:37:16.357Z    debug   subscriber/subscriber.go:137    new notification event from sidechain   {"name": "Transfer"}
2023-01-20T11:37:16.358Z    debug   event/listener.go:326   event parser not set    {"chain": "morph", "script hash LE": "f7a77b58e2581cb3f363977295ff870e42c42555", "event type": "Transfer"}
2023-01-20T11:37:16.359Z    debug   subscriber/subscriber.go:137    new notification event from sidechain   {"name": "TransferX"}
2023-01-20T11:37:16.359Z    debug   event/listener.go:326   event parser not set    {"chain": "morph", "script hash LE": "f7a77b58e2581cb3f363977295ff870e42c42555", "event type": "TransferX"}
2023-01-20T11:37:16.360Z    debug   innerring/innerring.go:235  new block   {"index": 96}
2023-01-20T11:37:16.361Z    debug   event/listener.go:394   notary parser not set   {"chain": "morph", "contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "method": "put"}
2023-01-20T11:37:16.566Z    INFO    persisted to disk   {"blocks": 1, "keys": 49, "headerHeight": 96, "blockHeight": 96, "took": "5.623832ms"}
2023-01-20T11:37:17.000Z    debug   session/executor.go:31  serving request...  {"component": "SessionService", "request": "Create"}
2023-01-20T11:37:17.035Z    INFO    runtime log {"tx": "cc3d1bf533286df96c82f7981b8b19ab2670cd92366a98493835e127645798cd", "script": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "msg": "remove container"}
2023-01-20T11:37:17.044Z    debug   client/notary.go:522    notary request invoked  {"method": "delete", "valid_until_block": 200, "fallback_valid_for": 40, "tx_hash": "1b016d77ada85fd9e5b35d0ddd9c98947145d54e815c12665952a5adaae60e92"}
2023-01-20T11:37:17.047Z    info    container/handlers.go:32    notification    {"type": "container delete", "id": "2sp9MAJAmJNxS9cYoz7fuq2juDA46Y4JaHF9fXTEkQ8P"}
2023-01-20T11:37:17.055Z    debug   client/notary.go:404    notary request with prepared main TX invoked    {"fallback_valid_for": 40, "tx_hash": "567f3cbb420a958272b2f01950988e8c0bf07685923ee376a34e6154d361812b"}
2023-01-20T11:37:17.350Z    INFO    sending PrepareRequest  {"height": 97, "view": 0}
2023-01-20T11:37:17.350Z    INFO    sending Commit  {"height": 97, "view": 0}
2023-01-20T11:37:17.352Z    INFO    approving block {"height": 97, "hash": "eefa343ae235c75d9e528bf1c5e5a957a313c1f4c10a00f7f8a7271e9bffe3e6", "tx_count": 1, "merkle": "ce1282a8af2dd7e3184e8f9602f2cb1846d35db752c1ae1a3374746a78690715", "prev": "91ea342cf82c017c72355a5967e46ba624aefdad84b0e675e8c43ccf85482f77"}
2023-01-20T11:37:17.352Z    INFO    runtime log {"tx": "150769786a7474331aaec152b75dd34618cbf202968f4e18e3d72dafa88212ce", "script": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "msg": "remove container"}
2023-01-20T11:37:17.353Z    INFO    initializing dbft   {"height": 98, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:17.355Z    debug   innerring/innerring.go:235  new block   {"index": 97}
2023-01-20T11:37:17.355Z    debug   event/listener.go:394   notary parser not set   {"chain": "morph", "contract": "4fe02bcf074db1b6a5b71c13e3ac04e4bcfc3a96", "method": "delete"}
2023-01-20T11:37:17.356Z    debug   subscriber/subscriber.go:137    new notification event from sidechain   {"name": "DeleteSuccess"}
2023-01-20T11:37:17.356Z    debug   neofs-node/container.go:117 container removal event's receipt   {"id": "2sp9MAJAmJNxS9cYoz7fuq2juDA46Y4JaHF9fXTEkQ8P"}
2023-01-20T11:37:17.357Z    debug   neofs-node/morph.go:238 new block   {"index": 97}
2023-01-20T11:37:17.565Z    INFO    persisted to disk   {"blocks": 1, "keys": 31, "headerHeight": 97, "blockHeight": 97, "took": "3.769574ms"}
2023-01-20T11:37:18.353Z    INFO    sending PrepareRequest  {"height": 98, "view": 0}
2023-01-20T11:37:18.353Z    INFO    sending Commit  {"height": 98, "view": 0}
2023-01-20T11:37:18.353Z    INFO    approving block {"height": 98, "hash": "5167f23a92c2f21b4e3e6fed3eeda8732e10ac8b06cd1a35fbe5150c26749991", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "eefa343ae235c75d9e528bf1c5e5a957a313c1f4c10a00f7f8a7271e9bffe3e6"}
2023-01-20T11:37:18.354Z    INFO    initializing dbft   {"height": 99, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:18.354Z    debug   innerring/innerring.go:235  new block   {"index": 98}
2023-01-20T11:37:18.355Z    debug   neofs-node/morph.go:238 new block   {"index": 98}
2023-01-20T11:37:18.565Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 98, "blockHeight": 98, "took": "2.542078ms"}
2023-01-20T11:37:19.354Z    INFO    sending PrepareRequest  {"height": 99, "view": 0}
2023-01-20T11:37:19.355Z    INFO    sending Commit  {"height": 99, "view": 0}
2023-01-20T11:37:19.356Z    INFO    approving block {"height": 99, "hash": "cea57969c015af4d77f18f44aaa474b0e82ec7b93fcaa8d26f03441d626e4efa", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "5167f23a92c2f21b4e3e6fed3eeda8732e10ac8b06cd1a35fbe5150c26749991"}
2023-01-20T11:37:19.357Z    INFO    initializing dbft   {"height": 100, "view": 0, "index": 0, "role": "Primary"}
2023-01-20T11:37:19.358Z    debug   innerring/innerring.go:235  new block   {"index": 99}
2023-01-20T11:37:19.359Z    debug   neofs-node/morph.go:238 new block   {"index": 99}
2023-01-20T11:37:19.567Z    INFO    persisted to disk   {"blocks": 1, "keys": 20, "headerHeight": 99, "blockHeight": 99, "took": "4.489724ms"}
2023-01-20T11:37:20.357Z    INFO    sending PrepareRequest  {"height": 100, "view": 0}
2023-01-20T11:37:20.358Z    INFO    sending Commit  {"height": 100, "view": 0}

@roman-khimov

roman-khimov commented 1 year ago

Seems to be a node issue to me, but let's have it there for now.

roman-khimov commented 1 year ago

In fact, this looks a lot like nspcc-dev/neofs-node#2155 and may be fixed by nspcc-dev/neofs-node#2176.

roman-khimov commented 1 year ago

Please retry now with new NeoFS node (after #50).

mialbu commented 1 year ago

Please retry now with new NeoFS node (after #50).

Hey @roman-khimov I've just tried to use neofs-aio on the latest commit, but I can't start the container. It works with commit 74b925abde8a96ea22882d73b1ad797d30d7d5fb where you changed the docker-compose to just use one image, but I run into the following error with commit da7afa705e4ab4351061a663eeceda631b8aad70:

image

I get the same error when using the latest commit (f6c31d6c33917817d2741356efb1a0462d824608).

I've cleared the local cache as mentioned in the README but that did not help.

roman-khimov commented 1 year ago

Ah, it's just missing from the Docker Hub. If you're to make it first, it'll be OK, but let's upload it to the Hub as well...

roman-khimov commented 1 year ago

Should be OK now either way: https://hub.docker.com/layers/nspccdev/neofs-aio/0.36.0/images/sha256-4cd2fef8eda536daa5525508dfde2888ff730d68dc89ff90cc20765c77dd3750?context=explore

roman-khimov commented 1 year ago

We've got 0.37.0 version now, please check.

mialbu commented 1 year ago

We've got 0.37.0 version now, please check.

Hey @roman-khimov, it works with 0.37.0, awesome! Sorry for the late response.