vegaprotocol / vega

A Go implementation of the Vega Protocol, a protocol for creating and trading derivatives on a fully decentralised network.
https://vega.xyz
GNU Affero General Public License v3.0
39 stars 22 forks source link

[Bug]: When one of the rpc_servers in tendermint config is not healthy enough data-node syncing is failing #10270

Open daniel1302 opened 11 months ago

daniel1302 commented 11 months ago

Problem encountered

I am not sure if it is a bug, but definitely makes starting the node annoying.

The timeline:

Observed behaviour

I got the following error after 3 days of syncing the network history:

Dec 18 20:25:40 data-node-vega visor[1735]: 2023-12-18T20:25:40.730Z        ERROR        core        node/node.go:194        problem starting blockchain        {"error": "failed to start state sync: failed to set up light client state provider: post failed: Post \"http://api1.vega.community:26657\": context deadline exceeded"}

Then vegavisor restarted binaries and downloading 10 mln of blocks from the network history started again.

Expected behaviour

I am not sure what the should be correct behaviour, but we should not lose our syncing progress when something is not right :( We can have much more issues than only a single tendermint peer issue like networking issue, some hiccups on the server and all of the above will end with failure and syncing from the beginning.

Steps to reproduce

1. Start syncing data-node from the network history
2. Add the following line in the `/etc/hosts`: `123.123.123.123 api1.vega.community`  - It will make all requests to api1.vega.community failing

Software version

v0.73.9

Failing test

No response

Jenkins run

No response

Configuration used

Data node config:

AutoInitialiseFromNetworkHistory = true
ChainID = "vega-mainnet-0011"
GatewayEnabled = true
MaxMemoryPercent = 33

[API]
  CoreNodeGRPCPort = 3002
  CoreNodeIP = "127.0.0.1"
  IP = "0.0.0.0"
  Level = "Info"
  MaxSubscriptionPerClient = 250
  Port = 3007
  Reflection = false
  StreamRetries = 3
  Timeout = "5s"
  WebUIEnabled = false
  WebUIPort = 3006

  [API.RateLimit]
    BanFor = "10m0s"
    Burst = 1000
    Enabled = true
    Rate = 300.0
    TTL = "1h0m0s"
    TrustedProxies = ["127.0.0.1"]

[Admin]
  Level = "Info"

  [Admin.Server]
    HTTPPath = "/datanode/rpc"
    SocketPath = "/tmp/datanode.sock"

[Broker]
  EventBusClientBufferSize = 100000
  Level = "Info"
  PanicOnError = false
  SocketServerInboundBufferSize = 10000
  SocketServerOutboundBufferSize = 10000
  UseBufferedEventSource = true
  UseEventFile = false

  [Broker.BufferedEventSourceConfig]
    Archive = true
    ArchiveMaximumSizeBytes = 1000000000
    EventsPerFile = 10000000
    SendChannelBufferSize = 10000

  [Broker.FileEventSourceConfig]
    Directory = "events"
    SendChannelBufferSize = 1000
    TimeBetweenBlocks = "1s"

  [Broker.SocketConfig]
    IP = "0.0.0.0"
    MaxReceiveTimeouts = 3
    Port = 3005
    TransportType = "tcp"

[CandlesV2]
  Level = "Info"

  [CandlesV2.CandleStore]
    DefaultCandleIntervals = ""

  [CandlesV2.CandleUpdates]
    CandleUpdatesStreamBufferSize = 100
    CandleUpdatesStreamInterval = "1s"
    CandleUpdatesStreamSubscriptionMsgBufferSize = 100
    CandlesFetchTimeout = "10s"

[Gateway]
  AutoCertDomain = ""
  CertificateFile = ""
  GraphQLPlaygroundEnabled = true
  HTTPSEnabled = false
  IP = "0.0.0.0"
  KeyFile = ""
  Level = "Info"
  MaxSubscriptionPerClient = 250
  Port = 3008
  SubscriptionRetries = 3
  Timeout = "5s"

  [Gateway.CORS]
    AllowedOrigins = ["*"]
    MaxAge = 7200

  [Gateway.GraphQL]
    ComplexityLimit = 0
    Enabled = true
    Endpoint = "/graphql"

  [Gateway.Node]
    IP = "0.0.0.0"
    Port = 3007

  [Gateway.REST]
    APMEnabled = true
    Enabled = true

  [Gateway.RateLimit]
    BanFor = "10m0s"
    Burst = 100
    Enabled = true
    Rate = 20.0
    TTL = "1h0m0s"
    TrustedProxies = ["127.0.0.1"]

[Logging]
  Environment = "dev"

  [Logging.Custom]

    [Logging.Custom.Zap]
      Development = true
      Encoding = "console"
      ErrorOutputPaths = ["stderr"]
      Level = -1
      OutputPaths = ["stdout"]

    [Logging.Custom.ZapEncoder]
      CallerKey = "C"
      EncodeCaller = "short"
      EncodeDuration = "string"
      EncodeLevel = "capital"
      EncodeName = "full"
      EncodeTime = "iso8601"
      LevelKey = "L"
      LineEnding = "\n"
      MessageKey = "M"
      NameKey = "N"
      TimeKey = "T"

[Metrics]
  Enabled = false
  Level = "Info"
  Path = "/metrics"
  Port = 2112
  Timeout = "5s"

[NetworkHistory]
  Enabled = true
  FetchRetryMax = 10
  Level = "Info"
  Publish = true
  RetryTimeout = "15s"
  WipeOnStartup = false

  [NetworkHistory.Initialise]
    GrpcAPIPorts = []
    MinimumBlockCount = 10000000
    TimeOut = "96h0m0s"
    Timeout = "4h"
    ToSegment = ""

  [NetworkHistory.Snapshot]
    WaitForCreationLockTimeout = "5m0s"

  [NetworkHistory.Store]
    BootstrapPeers = ["/dns/api1.vega.community/tcp/4001/ipfs/12D3KooWDZrusS1p2XyJDbCaWkVDCk2wJaKi6tNb4bjgSHo9yi5Q", "/dns/api2.vega.community/tcp/4001/ipfs/12D3KooWEH9pQd6P7RgNEpwbRyavWcwrAdiy9etivXqQZzd7Jkrh", "/dns/api3.vega.community/tcp/4001/ipfs/12D3KooWEH9pQd6P7RgNEpwbRyavWcwrAdiy9etivXqQZzd7Jkrh"]
    GarbageCollectionInterval = "24h0m0s"
    HistoryRetentionBlockSpan = 9223372036854775807
    PeerID = "12D3KooWHRWPn5uAdx1262e8PwWjWsmcgfhr6T2PatPFYQ7aSrpk"
    PrivKey = "<secret>"
    SwarmKeyOverride = ""
    SwarmPort = 4001

[Pprof]
  BlockProfileRate = 0
  Enabled = false
  Level = "Info"
  MutexProfileFraction = 0
  Port = 6060
  ProfilesDir = "/tmp"
  WriteEvery = "15m0s"

[SQLStore]
  DisableMinRetentionPolicyCheckForUseInSysTestsOnly = false
  FanOutBufferSize = 1000
  Level = "Info"
  RetentionPeriod = "forever"
  UseEmbedded = false
  VerboseMigration = false
  WipeOnStartup = false

  [SQLStore.ConnectionConfig]
    Database = "data_node_db"
    Host = "postgresql-vega.local.mainnet.community"
    MaxConnLifetime = "30m0s"
    MaxConnLifetimeJitter = "5m0s"
    MaxConnPoolSize = 0
    MinConnPoolSize = 0
    Password = "vega"
    Port = 5432
    SocketDir = "/tmp"
    Username = "vega"

    [SQLStore.ConnectionConfig.RuntimeParams]

  [SQLStore.ConnectionRetryConfig]
    InitialInterval = "1s"
    MaxElapsedTime = "1m0s"
    MaxInterval = "10s"
    MaxRetries = 10

  [SQLStore.LogRotationConfig]
    MaxAge = 2
    MaxSize = 100

[Service]
  Level = "Info"

Tendermint config:

abci = "socket"
db_backend = "goleveldb"
db_dir = "data"
fast_sync = true
filter_peers = false
genesis_file = "config/genesis.json"
log_format = "plain"
log_level = "info"
moniker = "data-node-vega"
node_key_file = "config/node_key.json"
pex = true
priv_validator_key_file = "config/priv_validator_key.json"
priv_validator_laddr = ""
priv_validator_state_file = "data/priv_validator_state.json"
proxy_app = "tcp://127.0.0.1:26658"

[consensus]
  create_empty_blocks = true
  create_empty_blocks_interval = "0s"
  double_sign_check_height = 0
  peer_gossip_sleep_duration = "100ms"
  peer_query_maj23_sleep_duration = "2s"
  skip_timeout_commit = false
  timeout_commit = "1s"
  timeout_precommit = "1s"
  timeout_precommit_delta = "500ms"
  timeout_prevote = "1s"
  timeout_prevote_delta = "500ms"
  timeout_propose = "3s"
  timeout_propose_delta = "500ms"
  wal_file = "data/cs.wal/wal"

[fastsync]
  version = "v0"

[instrumentation]
  max_open_connections = 3
  namespace = "cometbft"
  prometheus = false
  prometheus_listen_addr = ":26660"

[mempool]
  broadcast = true
  cache_size = 10000
  keep-invalid-txs-in-cache = false
  max_batch_bytes = 0
  max_tx_bytes = 1048576
  max_txs_bytes = 1073741824
  recheck = true
  size = 5000
  ttl-duration = "0s"
  ttl-num-blocks = 0
  version = "v0"
  wal_dir = ""

[p2p]
  addr_book_file = "config/addrbook.json"
  addr_book_strict = true
  allow_duplicate_ip = false
  dial_timeout = "3s"
  external_address = ""
  flush_throttle_timeout = "100ms"
  handshake_timeout = "20s"
  laddr = "tcp://0.0.0.0:26656"
  max_num_inbound_peers = 40
  max_num_outbound_peers = 10
  max_packet_msg_payload_size = 1024
  persistent_peers = ""
  persistent_peers_max_dial_period = "0s"
  pex = true
  private_peer_ids = ""
  recv_rate = 5120000
  seed_mode = false
  seeds = "b0db58f5651c85385f588bd5238b42bedbe57073@13.125.55.240:26656,abe207dae9367995526812d42207aeab73fd6418@18.158.4.175:26656,198ecd046ebb9da0fc5a3270ee9a1aeef57a76ff@144.76.105.240:26656,211e435c2162aedb6d687409d5d7f67399d198a9@65.21.60.252:26656,c5b11e1d819115c4f3974d14f76269e802f3417b@34.88.191.54:26656,61051c21f083ee30c835a34a0c17c5d1ceef3c62@51.178.75.45:26656,b0db58f5651c85385f588bd5238b42bedbe57073@18.192.52.234:26656,36a2ca7bb6a50427be2181c8ebb7f62ac62ebaf5@m2.vega.community:26656,9903c02a0ff881dc369fc7daccb22c1f9680d2dd@api0.vega.community:26656,9903c02a0ff881dc369fc7daccb22c1f9680d2dd@api0.vega.community:26656,32d7380b195c088c0605c5d24bcf15ff1dade05f@api1.vega.community:26656,4f26ec99d3cf6f0e9e973c0a5f3da87d89ec6677@api2.vega.community:26656,eafacd11af53cd9fb2a14eada53485779cbee4ab@api3.vega.community:26656,9de3ca2bbeb62d165d39acbbcf174e7ac3a6b7c9@be3.vega.community:26656"
  send_rate = 5120000
  unconditional_peer_ids = ""
  upnp = false

[rpc]
  cors_allowed_headers = ["Origin", "Accept", "Content-Type", "X-Requested-With", "X-Server-Time"]
  cors_allowed_methods = ["HEAD", "GET", "POST"]
  cors_allowed_origins = []
  experimental_close_on_slow_client = false
  experimental_subscription_buffer_size = 200
  experimental_websocket_write_buffer_size = 200
  grpc_laddr = ""
  grpc_max_open_connections = 900
  laddr = "tcp://127.0.0.1:26657"
  max_body_bytes = 1000000
  max_header_bytes = 1048576
  max_open_connections = 900
  max_subscription_clients = 100
  max_subscriptions_per_client = 5
  pprof_laddr = ""
  timeout_broadcast_tx_commit = "10s"
  tls_cert_file = ""
  tls_key_file = ""
  unsafe = false

[statesync]
  chunk_fetchers = "4"
  chunk_request_timeout = "10s"
  discovery_time = "15s"
  enable = true
  rpc_servers = "api0.vega.community:26657,api2.vega.community:26657,api3.vega.community:26657"
  temp_dir = ""
  trust_hash = "d422d176967352b73a4a4a35f9c7e0f7d31910c16c74edabf9196c81150d439b"
  trust_height = 27537100
  trust_period = "672h0m0s"

[storage]
  discard_abci_responses = false

[tx_index]
  indexer = "kv"
  psql-conn = ""

Relevant log output

Dec 18 20:25:02 data-node-vega visor[1736]: 2023-12-18T20:25:02.995Z        INFO        datanode.networkHistory.service        snapshot/service_load_snapshot.go:302        executing sql: ALTER TABLE stop_orders_live SET (autovacuum_enabled = true)
Dec 18 20:25:02 data-node-vega visor[1736]: 2023-12-18T20:25:02.995Z        INFO        datanode.networkHistory.service        snapshot/service_load_snapshot.go:302        executing sql: ALTER TABLE team_members SET (autovacuum_enabled = true)
Dec 18 20:25:02 data-node-vega visor[1736]: 2023-12-18T20:25:02.996Z        INFO        datanode.networkHistory.service        snapshot/service_load_snapshot.go:302        executing sql: ALTER TABLE teams SET (autovacuum_enabled = true)
Dec 18 20:25:02 data-node-vega visor[1736]: 2023-12-18T20:25:02.996Z        INFO        datanode.networkHistory.service        snapshot/service_load_snapshot.go:302        executing sql: ALTER TABLE trades SET (autovacuum_enabled = true)
Dec 18 20:25:02 data-node-vega visor[1736]: 2023-12-18T20:25:02.997Z        INFO        datanode.networkHistory.service        snapshot/service_load_snapshot.go:302        executing sql: ALTER TABLE transfer_fees SET (autovacuum_enabled = true)
Dec 18 20:25:02 data-node-vega visor[1736]: 2023-12-18T20:25:02.997Z        INFO        datanode.networkHistory.service        snapshot/service_load_snapshot.go:302        executing sql: ALTER TABLE transfers SET (autovacuum_enabled = true)
Dec 18 20:25:02 data-node-vega visor[1736]: 2023-12-18T20:25:02.998Z        INFO        datanode.networkHistory.service        snapshot/service_load_snapshot.go:302        executing sql: ALTER TABLE volume_discount_programs SET (autovacuum_enabled = true)
Dec 18 20:25:02 data-node-vega visor[1736]: 2023-12-18T20:25:02.998Z        INFO        datanode.networkHistory.service        snapshot/service_load_snapshot.go:302        executing sql: ALTER TABLE volume_discount_stats SET (autovacuum_enabled = true)
Dec 18 20:25:02 data-node-vega visor[1736]: 2023-12-18T20:25:02.999Z        INFO        datanode.networkHistory.service        snapshot/service_load_snapshot.go:302        executing sql: ALTER TABLE votes SET (autovacuum_enabled = true)
Dec 18 20:25:02 data-node-vega visor[1736]: 2023-12-18T20:25:02.999Z        INFO        datanode.networkHistory.service        snapshot/service_load_snapshot.go:302        executing sql: ALTER TABLE withdrawals SET (autovacuum_enabled = true)
Dec 18 20:25:03 data-node-vega visor[1736]: 2023-12-18T20:25:03.115Z        INFO        datanode.networkHistory.service        networkhistory/service.go:278        recreating continuous aggregate data
Dec 18 20:25:03 data-node-vega visor[1726]: 2023-12-18T20:25:03.212Z        DEBUG        visor        visor/visor.go:174        failed to get upgrade status from API        {"error": "failed to call protocolupgrade.UpgradeStatus method: failed to post data \"{\\\"method\\\":\\\"protocolupgrade.UpgradeStatus\\\",\\\"params\\\":[null],\\\"id\\\":1017643116865527121}\": Post \"http://unix/rpc\": dial unix /tmp/vega.sock: connect: no such file or directory"}
Dec 18 20:25:03 data-node-vega visor[1736]: 2023-12-18T20:25:03.278Z        INFO        datanode.networkHistory.service        networkhistory/service.go:283        loaded all available data into datanode        {"result": "{LoadedFromHeight:27657101 LoadedToHeight:27657700 RowsLoaded:544925}", "time taken": "19.513282879s"}
Dec 18 20:25:03 data-node-vega visor[1736]: 2023-12-18T20:25:03.278Z        INFO        datanode.start.persistentPre        networkhistory/initialise.go:89        loaded history from height 27657101 to 27657700 into the datanode
Dec 18 20:25:04 data-node-vega visor[1735]: 2023-12-18T20:25:04.269Z        ERROR        core.protocol.broker.socket-client        broker/socket_client.go:185        failed to connect, retrying        {"error": "dial tcp 127.0.0.1:3005: connect: connection refused", "peer": "tcp://127.0.0.1:3005"}
Dec 18 20:25:05 data-node-vega visor[1726]: 2023-12-18T20:25:05.211Z        DEBUG        visor        visor/visor.go:174        failed to get upgrade status from API        {"error": "failed to call protocolupgrade.UpgradeStatus method: failed to post data \"{\\\"method\\\":\\\"protocolupgrade.UpgradeStatus\\\",\\\"params\\\":[null],\\\"id\\\":3403494465746094055}\": Post \"http://unix/rpc\": dial unix /tmp/vega.sock: connect: no such file or directory"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.676Z        INFO        datanode.start.persistentPre        networkhistory/initialise.go:197        got most recent history segment        {"segment": "from_height:27657401  to_height:27657700  history_segment_id:\"QmZm7Jf2dN3LaSzNbMh5jg7GwhUuma347SBCuDkPM2CWt5\"  previous_history_segment_id:\"QmdXCny1qvea2zQRV8v28kjZJmXnR3M3vpdBLF8YAiWFUD\"  database_version:54  chain_id:\"vega-mainnet-0011\"", "peer": "api2.vega.community:3007"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.679Z        INFO        datanode.start.persistentPre        start/node_pre.go:124        data node height 27657700 is already at or beyond the height of the most recent history segment 27657700, no further history to load
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.679Z        INFO        datanode.start.persistentPre        start/node_pre.go:131        Initialized from network history
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.679Z        INFO        datanode.start.persistentPre        start/node_pre.go:159        Applying Data Retention Policies
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.708Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "conflated_balances", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.709Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "conflated_margin_levels", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.709Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "conflated_positions", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.710Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "trades_candle_15_minutes", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.710Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "trades_candle_1_day", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.711Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "trades_candle_1_hour", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.711Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "trades_candle_1_minute", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.712Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "trades_candle_5_minutes", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.713Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "trades_candle_6_hours", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.713Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "blocks", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.714Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "balances", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.714Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "ledger", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.715Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "orders", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.715Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "trades", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.716Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "market_data", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.716Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "rewards", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.717Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "delegations", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.718Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "markets", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.718Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "deposits", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.719Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "withdrawals", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.719Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "margin_levels", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.720Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "checkpoints", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.720Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "positions", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.721Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "liquidity_provisions", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.721Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "stop_orders", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.722Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "funding_period_data_points", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.722Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "party_activity_streaks", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.723Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "referral_programs", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.723Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "referral_set_stats", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.724Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "oracle_data", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.724Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "oracle_data_oracle_specs", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.725Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "funding_payment", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.725Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "volume_discount_programs", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.726Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "volume_discount_stats", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.727Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "fees_stats", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.727Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "party_locked_balances", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.728Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "party_vesting_balances", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.728Z        INFO        datanode.start.persistentPre        sqlstore/sqlstore.go:436        Setting retention policy        {"entity": "party_vesting_stats", "policy": "forever"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.728Z        INFO        datanode.start.persistentPre        start/node_pre.go:166        Enabling SQL stores
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.774Z        DEBUG        datanode.start.persistentPre.connection-source        sqlstore/market_data.go:135        Retrieving markets data from Postgres
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.787Z        INFO        datanode.buffered-event-source        broker/buffered_event_source.go:99        Starting buffered event source with a max buffered event, and events per buffer file size        {"events-per-file": 10000000}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.791Z        INFO        datanode.start.runNode        start/node.go:175        Vega data node startup complete
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.791Z        INFO        datanode.api.grpc        api/server.go:425        Starting gRPC based API        {"addr": "0.0.0.0", "port": "3007"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.792Z        INFO        datanode.broker.eventsource.socket-server        broker/socket_server.go:101        Starting broker socket server        {"addr": "0.0.0.0", "port": 3005}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.791Z        INFO        datanode.admin.server        admin/server.go:55        Starting Data Node Admin Server<>RPC based API        {"socket-path": "/tmp/datanode.sock", "http-path": "/datanode/rpc"}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.794Z        INFO        datanode.admin.server        admin/server.go:93        Data Node Admin Server<>RPC based API started
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.794Z        INFO        datanode.sqlstore-broker        broker/sqlstore_broker.go:135        waiting for first unprocessed block, last processed block height: 27657700
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.793Z        WARN        datanode.gateway.gql        graphql/server.go:221        graphql playground enabled, this is not a recommended setting for production
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.800Z        INFO        datanode.gateway        server/server.go:115        Starting http based API        {"addr": "0.0.0.0", "port": 3008}
Dec 18 20:25:05 data-node-vega visor[1736]: 2023-12-18T20:25:05.801Z        WARN        datanode.gateway        server/server.go:146        GraphQL server is not configured to use HTTPS, which is required for subscriptions to work. Please see README.md for help configuring
Dec 18 20:25:07 data-node-vega visor[1726]: 2023-12-18T20:25:07.211Z        DEBUG        visor        visor/visor.go:174        failed to get upgrade status from API        {"error": "failed to call protocolupgrade.UpgradeStatus method: failed to post data \"{\\\"method\\\":\\\"protocolupgrade.UpgradeStatus\\\",\\\"params\\\":[null],\\\"id\\\":4198874351219881429}\": Post \"http://unix/rpc\": dial unix /tmp/vega.sock: connect: no such file or directory"}
Dec 18 20:25:09 data-node-vega visor[1726]: 2023-12-18T20:25:09.212Z        DEBUG        visor        visor/visor.go:174        failed to get upgrade status from API        {"error": "failed to call protocolupgrade.UpgradeStatus method: failed to post data \"{\\\"method\\\":\\\"protocolupgrade.UpgradeStatus\\\",\\\"params\\\":[null],\\\"id\\\":4270773739309655987}\": Post \"http://unix/rpc\": dial unix /tmp/vega.sock: connect: no such file or directory"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.270Z        INFO        core.protocol.broker.socket-client        broker/socket_client.go:89        New broker connection event        {"eventType": "Attaching", "id": 1365504217, "address": "tcp://127.0.0.1:3005"}
Dec 18 20:25:09 data-node-vega visor[1736]: 2023-12-18T20:25:09.270Z        INFO        datanode.broker.eventsource.socket-server        broker/socket_server.go:105        New broker connection event        {"eventType": "Attaching", "id": 938480157, "address": "tcp://[::]:3005"}
Dec 18 20:25:09 data-node-vega visor[1736]: 2023-12-18T20:25:09.270Z        INFO        datanode.broker.eventsource.socket-server        broker/socket_server.go:105        New broker connection event        {"eventType": "Attached", "id": 938480157, "address": "tcp://[::]:3005"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.270Z        INFO        core.protocol.broker.socket-client        broker/socket_client.go:89        New broker connection event        {"eventType": "Attached", "id": 1365504217, "address": "tcp://127.0.0.1:3005"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.282Z        INFO        core.protocol.spam        spam/engine.go:163        Spam protection started
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.401Z        INFO        core.protocol.pow        pow/engine.go:137        PoW spam protection started
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.402Z        INFO        core.coreapi        coreapi/service.go:69        starting accounts core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:74        starting assets core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:79        starting network parameters core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:84        starting network limits core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:89        starting parties core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:94        starting validators core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:99        starting markets core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:104        starting proposals core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:109        starting marketsData core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:114        starting votes core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:119        starting parties stake core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.coreapi        coreapi/service.go:124        starting delegations core api
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core        node/node.go:174        Vega startup complete        {"node-mode": "full"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.403Z        INFO        core.api.restproxy        rest/server.go:79        Starting REST<>GRPC based API        {"addr": "0.0.0.0", "port": 3003}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.404Z        INFO        core.api.grpc        api/grpc.go:248        Starting gRPC based API        {"addr": "0.0.0.0", "port": "3002"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.404Z        INFO        core.admin.non-validator-server        admin/server.go:116        Starting Server<>RPC based API        {"socket-path": "/tmp/vega.sock", "http-path": "/rpc"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.405Z        INFO        core.admin.non-validator-server        admin/server.go:148        Serving Server<>RPC based API
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.581Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting multiAppConn service", "impl": "multiAppConn"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.582Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting localClient service", "impl": "localClient"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.582Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting localClient service", "impl": "localClient"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.582Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting localClient service", "impl": "localClient"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.582Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting localClient service", "impl": "localClient"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.583Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting EventBus service", "impl": "EventBus"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.583Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting PubSub service", "impl": "PubSub"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.622Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting IndexerService service", "impl": "IndexerService"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.623Z        INFO        tendermint        node/node.go:337        Version info        {"cmtbft_version": "0.34.29", "abci": "0.17.0", "block": 11, "p2p": 8, "commit_hash": ""}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.623Z        INFO        tendermint        node/node.go:358        This node is not a validator        {"addr": "E80D35B2CACDFD844494435936A97660F278A833", "pubKey": "PubKeyEd25519{F9FE8A7D2D6139247C9837FF932E93298D22D6170F85C1ADE580E74423648DCB}"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.660Z        INFO        tendermint        node/node.go:598        P2P Node ID        {"ID": "94e21d8f0e01c3d97c211a47da948cdee9087f77", "file": "/home/vega/tendermint_home/config/node_key.json"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.660Z        INFO        tendermint        p2p/switch.go:612        Adding persistent peers        {"addrs": []}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.660Z        INFO        tendermint        p2p/switch.go:630        Adding unconditional peer ids        {"ids": []}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.661Z        INFO        tendermint        pex/addrbook.go:187        Add our address to book        {"addr": "94e21d8f0e01c3d97c211a47da948cdee9087f77@0.0.0.0:26656"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.680Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Node service", "impl": "Node"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.699Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting P2P Switch service", "impl": "P2P Switch"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.699Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting BlockchainReactor service", "impl": "BlockchainReactor"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.699Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Consensus service", "impl": "ConsensusReactor"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.699Z        INFO        tendermint        server/http_server.go:54        serve        {"msg": "Starting RPC HTTP server on 127.0.0.1:26657"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.699Z        INFO        tendermint        consensus/reactor.go:76        Reactor         {"waitSync": true}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.700Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Evidence service", "impl": "Evidence"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.700Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting StateSync service", "impl": "StateSync"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.700Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting PEX service", "impl": "PEX"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.700Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting AddrBook service", "impl": "AddrBook"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.793Z        INFO        tendermint        pex/file.go:22        Saving AddrBook to file        {"size": 0}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.793Z        INFO        tendermint        pex/pex_reactor.go:477        Ensure peers        {"numOutPeers": 0, "numInPeers": 0, "numDialing": 0, "numToDial": 10}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.803Z        INFO        tendermint        node/node.go:655        Starting state sync
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.803Z        INFO        tendermint        pex/pex_reactor.go:550        No addresses to dial. Falling back to seeds
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.806Z        INFO        tendermint        light/client.go:200        Downloading trusted light block using options
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.885Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Peer service", "impl": "Peer{MConn{18.192.52.234:26656} b0db58f5651c85385f588bd5238b42bedbe57073 out}"}
Dec 18 20:25:09 data-node-vega visor[1735]: 2023-12-18T20:25:09.885Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting MConnection service", "impl": "MConn{18.192.52.234:26656}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.259Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Peer service", "impl": "Peer{MConn{35.228.151.143:26656} 17ff66be2fbb555b6f2e4b9ccde5b274abb45e48 out}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.259Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting MConnection service", "impl": "MConn{35.228.151.143:26656}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.294Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Peer service", "impl": "Peer{MConn{176.9.125.110:26656} 874f6509d7806d7d5f01849669aa3e83c986b6db out}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.294Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting MConnection service", "impl": "MConn{176.9.125.110:26656}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.297Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Peer service", "impl": "Peer{MConn{164.90.205.53:26656} c4d07d8bab3e3860c7334559fc451d35caab231e out}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.297Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting MConnection service", "impl": "MConn{164.90.205.53:26656}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.319Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Peer service", "impl": "Peer{MConn{209.250.245.27:26656} 20122bdd674e86f5f97f9083d6ba02d1167183e9 out}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.319Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting MConnection service", "impl": "MConn{209.250.245.27:26656}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.321Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Peer service", "impl": "Peer{MConn{65.21.60.252:26656} 211e435c2162aedb6d687409d5d7f67399d198a9 out}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.322Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting MConnection service", "impl": "MConn{65.21.60.252:26656}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.346Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Peer service", "impl": "Peer{MConn{164.92.138.136:26656} 9903c02a0ff881dc369fc7daccb22c1f9680d2dd out}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.346Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting MConnection service", "impl": "MConn{164.92.138.136:26656}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.383Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Peer service", "impl": "Peer{MConn{165.232.126.207:26656} e5cf7f7e0399a499a5662821b5ea202f3cb7f951 out}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.383Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting MConnection service", "impl": "MConn{165.232.126.207:26656}"}
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.546Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.547Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.574Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.574Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.574Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.575Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:10 data-node-vega visor[1735]: 2023-12-18T20:25:10.576Z        INFO        tendermint        pex/addrbook.go:542        new bucket is full, expiring new
Dec 18 20:25:11 data-node-vega visor[1735]: 2023-12-18T20:25:11.151Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting Peer service", "impl": "Peer{MConn{64.227.105.183:26656} 9de3ca2bbeb62d165d39acbbcf174e7ac3a6b7c9 out}"}
Dec 18 20:25:11 data-node-vega visor[1735]: 2023-12-18T20:25:11.151Z        INFO        tendermint        service/service.go:139        service start        {"msg": "Starting MConnection service", "impl": "MConn{64.227.105.183:26656}"}
Dec 18 20:25:39 data-node-vega visor[1735]: 2023-12-18T20:25:39.886Z        INFO        tendermint        pex/pex_reactor.go:477        Ensure peers        {"numOutPeers": 9, "numInPeers": 0, "numDialing": 0, "numToDial": 1}
Dec 18 20:25:40 data-node-vega visor[1735]: 2023-12-18T20:25:40.730Z        ERROR        core        node/node.go:194        problem starting blockchain        {"error": "failed to start state sync: failed to set up light client state provider: post failed: Post \"http://api1.vega.community:26657\": context deadline exceeded"}
Dec 18 20:25:40 data-node-vega visor[1735]: failed to start state sync: failed to set up light client state provider: post failed: Post "http://api1.vega.community:26657": context deadline exceeded
Dec 18 20:25:40 data-node-vega visor[1736]: 2023-12-18T20:25:40.738Z        INFO        datanode.broker.eventsource.socket-server        broker/socket_server.go:105        New broker connection event        {"eventType": "Detached", "id": 938480157, "address": "tcp://[::]:3005"}
Dec 18 20:25:40 data-node-vega visor[1726]: 2023-12-18T20:25:40.738Z        DEBUG        visor        visor/binaries_runner.go:111        Stopping binary        {"binaryPath": "/home/vega/vegavisor_home/current/vega"}
Dec 18 20:25:40 data-node-vega visor[1726]: 2023-12-18T20:25:40.760Z        ERROR        visor        visor/visor.go:146        Binaries executions has failed        {"error": "failed after waiting for binary /home/vega/vegavisor_home/current/vega [start --home /home/vega/vega_home --tendermint-home /home/vega/tendermint_home]: exit status 255"}
Dec 18 20:25:40 data-node-vega visor[1726]: 2023-12-18T20:25:40.760Z        INFO        visor        visor/visor.go:153        Binaries restart is scheduled        {"restartDelay": "5s"}
Dec 18 20:25:45 data-node-vega visor[1726]: 2023-12-18T20:25:45.760Z        INFO        visor        visor/visor.go:155        Restarting binaries        {"remainingRestarts": 2}
Dec 18 20:25:45 data-node-vega visor[1726]: 2023-12-18T20:25:45.761Z        INFO        visor        visor/visor.go:123        Restarting binaries
Dec 18 20:25:45 data-node-vega visor[1726]: 2023-12-18T20:25:45.761Z        DEBUG        visor        visor/binaries_runner.go:179        Preparing Vega args
Dec 18 20:25:45 data-node-vega visor[1726]: 2023-12-18T20:25:45.761Z        DEBUG        visor        visor/binaries_runner.go:150        Getting latest history segment from data node (will lock the latest LevelDB snapshot!)
Dec 18 20:25:45 data-node-vega visor[1726]: 2023-12-18T20:25:45.886Z        DEBUG        visor        visor/binaries_runner.go:156        Got latest history segment from data node        {"success": true}
Dec 18 20:25:45 data-node-vega visor[1726]: 2023-12-18T20:25:45.886Z        DEBUG        visor        visor/visor.go:174        failed to get upgrade status from API        {"error": "failed to call protocolupgrade.UpgradeStatus method: failed to post data \"{\\\"method\\\":\\\"protocolupgrade.UpgradeStatus\\\",\\\"params\\\":[null],\\\"id\\\":1135947240783207728}\": Post \"http://unix/rpc\": dial unix /tmp/vega.sock: connect: connection refused"}
Dec 18 20:25:45 data-node-vega visor[1726]: 2023-12-18T20:25:45.886Z        DEBUG        visor        visor/binaries_runner.go:194        Starting Vega binary
Dec 18 20:25:45 data-node-vega visor[1726]: 2023-12-18T20:25:45.887Z        DEBUG        visor        visor/binaries_runner.go:87        Starting binary        {"binaryPath": "/home/vega/vegavisor_home/current/vega", "args": ["start", "--home", "/home/vega/vega_home", "--tendermint-home", "/home/vega/tendermint_home", "--snapshot.load-from-block-height", "27657700"]}
Dec 18 20:25:45 data-node-vega visor[1726]: 2023-12-18T20:25:45.886Z        DEBUG        visor        visor/binaries_runner.go:200        Starting Data Node binary
wwestgarth commented 11 months ago

I don't think there is anything we can do about tendermint needing two available nodes to RPC with, but I do think this is a further indication that we have the order of events the wrong way around and we should be state-syncing in the core node before/at-the-same-time as the datanode is auto-initialising. Doing this will also fix this issue: https://github.com/vegaprotocol/vega/issues/10244

In general I think we have a lot of usability issues with using network-history that we need to resolve that I think we should address in controlled, planned way because the architecture of the network-history code in the data-node is clunky and "spaghetti". If we try to just throw in little fixes it'll just get worse. It needs a bit of a rewrite.

Heres a brief selection of things we need to address: Performance:

Usability:

Memory: