search

stacks-network / stacks-core

The Stacks blockchain implementation
https://docs.stacks.co
GNU General Public License v3.0
3.01k stars 673 forks source link

[Stacks 2.1] Experiencing PoX cycle rollback #3466

Closed lgalabru closed 1 year ago

lgalabru commented 1 year ago

Still performing some testing on the Bitcoin Stacks ops, and I'm experiencing a new kind of issue. This could be related to the fact that my node was tweaked for performing short reward cycles (for faster feedback loop), my config is the following: Pox Cycle: 10 blocks (6 rewards, 4 prepare) Epoch 2: 100 Epoch 2.05: 101 Epoch 2.1: 103 Pox 2 Activation: 110 I fetched /v2/pox after block 110, got the expected pox-2 values. I'm submitting a Bitcoin Stacks STX OP, which was included in Bitcoin Block 116. Fetching /v2/pox after block 117 was correctly returning the STX stacked over Bitcoin. After mining blocks 119, it looked the stacks-node did a rollback: fetching v2/info now returns 

  ...
  "peer_version": 4207599110,
  "pox_consensus": "f030fadc5678923a43c10bf5c9a60129a6093b10",
  "burn_block_height": 120,
  "stable_burn_block_height": 119,
  "stacks_tip_height": 7,
  ...

and v2/pox is returning

  ...
  "current_cycle": {
    "id": 0,
    "min_threshold_ustx": 20960000000000,
    "stacked_ustx": 0,
    "is_pox_active": false
  },
  "next_cycle": {
    "id": 1,
  ...

The following logs look suspicious to me:

Jan  4 19:04:13.596991 DEBG Processed PoX affirmations for reward cycle 1 (ThreadId(332), src/burnchains/affirmation.rs:1213)
Jan  4 19:04:13.597048 DEBG Inserted block 120 in 17ms (ThreadId(332), src/burnchains/burnchain.rs:1616)
Jan  4 19:04:13.597090 DEBG Received new burn block notice (ThreadId(13), src/chainstate/coordinator/mod.rs:386)
Jan  4 19:04:13.597125 DEBG Handle new burnchain block (ThreadId(13), src/chainstate/coordinator/mod.rs:1796)
Jan  4 19:04:13.597323 DEBG Override v1_unlock_height from 140 to 110 (ThreadId(1), testnet/stacks-node/src/config.rs:410)
Jan  4 19:04:13.598385 DEBG Open sortdb as 'readwrite', with index as '/devnet/krypton/burnchain/sortition/marf.sqlite' (ThreadId(1), src/chainstate/burn/db/sortdb.rs:2350)
Jan  4 19:04:13.600147 DEBG Stacks tip 41b7d8ac48227362ea5bca164d1b1e12d47a1bcc/abbba63d268582f3866b7afde3b4409c8798fdafb5143aea05dc1663a71b705c (txid a4a1153d659b111fd81a0b5bbada9bed13f7221c0467ec232d49335bca6ddb4e) has affirmation map 'pp' (ThreadId(13), src/chainstate/stacks/db/blocks.rs:2559)
Jan  4 19:04:13.600794 DEBG Migrated MARF data to schema 2 (ThreadId(1), src/chainstate/stacks/index/trie_sql.rs:166)
Jan  4 19:04:13.600915 DEBG Opened TrieFileStorage /devnet/krypton/burnchain/sortition/marf.sqlite; external blobs: false (ThreadId(1), src/chainstate/stacks/index/storage.rs:1450)
Jan  4 19:04:13.606607 DEBG Last-selected anchor block 00d6a7e6d6dd6f0d4b4e7f81b2345994b2577ab5/9400484bd3e9c47f9d0bea95b049dba0870e508934cf512206f5039787404ff0 is processed (ThreadId(13), src/chainstate/burn/db/sortdb.rs:3796)
Jan  4 19:04:13.607106 DEBG Heaviest anchor block affirmation map is `p` at height 120, Stacks tip is `pp`, sortition tip is `np` (ThreadId(13), src/chainstate/coordinator/mod.rs:896)
Jan  4 19:04:13.607243 INFO Sortition anchor block affirmation map `np` and/or Stacks affirmation map `pp` is no longer compatible with heaviest affirmation map p in reward cycles 0-2 (ThreadId(13), src/chainstate/coordinator/mod.rs:947)
Jan  4 19:04:13.607374 DEBG Canonical sortition tip is 3ab62de920c678ce840fe85839bb528611aa1c2b3e574aa5ef52a774a15dcbf4 height 119 (rc 1); changed reward cycle is 0 (ThreadId(13), src/chainstate/coordinator/mod.rs:1223)
Jan  4 19:04:13.607593 DEBG Find invalidated and revalidated sortitions at reward cycle 0 (ThreadId(13), src/chainstate/coordinator/mod.rs:994)
Jan  4 19:04:13.637626 DEBG No snapshot at height 110 has an affirmation map that is a prefix of `p` (ThreadId(13), src/chainstate/coordinator/mod.rs:1083)
Jan  4 19:04:13.637751 INFO Re-playing sortitions starting within reward cycle 0 burn height 109 (ThreadId(13), src/chainstate/coordinator/mod.rs:1097)
Jan  4 19:04:13.638272 DEBG Invalidate all descendants of 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (after height 100), revalidate some sortitions at and after height 108, and retry all orphaned Stacks blocks at or after height 101 (ThreadId(13), src/chainstate/coordinator/mod.rs:1332)
Jan  4 19:04:13.642693 DEBG Invalidate descendants of burn block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (ThreadId(13), src/chainstate/burn/db/sortdb.rs:3301)

Full logs

jcnelson commented 1 year ago

Your logs don't include that snippet

lgalabru commented 1 year ago

Apologies, this should be right logs: debg-trace.txt

jcnelson commented 1 year ago

Can you confirm what build of the node you are using?

lgalabru commented 1 year ago

The build was based on the branch you shared with me yesterday (that does not include your commits from today), I'll try to reproduce with a build more recent.

lgalabru commented 1 year ago

Ok, it looks like latest builds should be fixing this issue (1 successful test out of 1).

Cycle 2 - Pre bitcoin op

{
  "contract_id": "ST000000000000000000002AMW42H.pox-2",
  "pox_activation_threshold_ustx": 50286942145278,
  "first_burnchain_block_height": 100,
  "current_burnchain_block_height": 114,
  "prepare_phase_block_length": 4,
  "reward_phase_block_length": 6,
  "reward_slots": 12,
  "rejection_fraction": 25,
  "total_liquid_supply_ustx": 1005738842905579,
  "current_cycle": {
    "id": 1,
    "min_threshold_ustx": 20960000000000,
    "stacked_ustx": 0,
    "is_pox_active": false
  },
  "next_cycle": {
    "id": 2,
    "min_threshold_ustx": 20960000000000,
    "min_increment_ustx": 125717355363,
    "stacked_ustx": 0,
    "prepare_phase_start_block_height": 116,
    "blocks_until_prepare_phase": 2,
    "reward_phase_start_block_height": 120,
    "blocks_until_reward_phase": 6,
    "ustx_until_pox_rejection": 251434710726375
  },
  "min_amount_ustx": 20960000000000,
  "prepare_cycle_length": 4,
  "reward_cycle_id": 1,
  "reward_cycle_length": 10,
  "rejection_votes_left_required": 251434710726375,
  "next_reward_cycle_in": 6,
  "contract_versions": [
    {
      "contract_id": "ST000000000000000000002AMW42H.pox",
      "activation_burnchain_block_height": 100,
      "first_reward_cycle_id": 0
    },
    {
      "contract_id": "ST000000000000000000002AMW42H.pox-2",
      "activation_burnchain_block_height": 110,
      "first_reward_cycle_id": 2
    }
  ]
}

Cycle 2 - Post bitcoin op

{
  "contract_id": "ST000000000000000000002AMW42H.pox-2",
  "pox_activation_threshold_ustx": 50286942145278,
  "first_burnchain_block_height": 100,
  "current_burnchain_block_height": 116,
  "prepare_phase_block_length": 4,
  "reward_phase_block_length": 6,
  "reward_slots": 12,
  "rejection_fraction": 25,
  "total_liquid_supply_ustx": 1005738842905579,
  "current_cycle": {
    "id": 1,
    "min_threshold_ustx": 20960000000000,
    "stacked_ustx": 0,
    "is_pox_active": false
  },
  "next_cycle": {
    "id": 2,
    "min_threshold_ustx": 20960000000000,
    "min_increment_ustx": 125717355363,
    "stacked_ustx": 90000000000000,
    "prepare_phase_start_block_height": 116,
    "blocks_until_prepare_phase": 0,
    "reward_phase_start_block_height": 120,
    "blocks_until_reward_phase": 4,
    "ustx_until_pox_rejection": 251434710726375
  },
  "min_amount_ustx": 20960000000000,
  "prepare_cycle_length": 4,
  "reward_cycle_id": 1,
  "reward_cycle_length": 10,
  "rejection_votes_left_required": 251434710726375,
  "next_reward_cycle_in": 4,
  "contract_versions": [
    {
      "contract_id": "ST000000000000000000002AMW42H.pox",
      "activation_burnchain_block_height": 100,
      "first_reward_cycle_id": 0
    },
    {
      "contract_id": "ST000000000000000000002AMW42H.pox-2",
      "activation_burnchain_block_height": 110,
      "first_reward_cycle_id": 2
    }
  ]
}

Cycle 3

{
  "contract_id": "ST000000000000000000002AMW42H.pox-2",
  "pox_activation_threshold_ustx": 50286942145278,
  "first_burnchain_block_height": 100,
  "current_burnchain_block_height": 121,
  "prepare_phase_block_length": 4,
  "reward_phase_block_length": 6,
  "reward_slots": 12,
  "rejection_fraction": 25,
  "total_liquid_supply_ustx": 1005738842905579,
  "current_cycle": {
    "id": 2,
    "min_threshold_ustx": 20960000000000,
    "stacked_ustx": 90000000000000,
    "is_pox_active": true
  },
  "next_cycle": {
    "id": 3,
    "min_threshold_ustx": 20960000000000,
    "min_increment_ustx": 125717355363,
    "stacked_ustx": 90000000000000,
    "prepare_phase_start_block_height": 126,
    "blocks_until_prepare_phase": 5,
    "reward_phase_start_block_height": 130,
    "blocks_until_reward_phase": 9,
    "ustx_until_pox_rejection": 251434710726375
  },
  "min_amount_ustx": 20960000000000,
  "prepare_cycle_length": 4,
  "reward_cycle_id": 2,
  "reward_cycle_length": 10,
  "rejection_votes_left_required": 251434710726375,
  "next_reward_cycle_in": 9,
  "contract_versions": [
    {
      "contract_id": "ST000000000000000000002AMW42H.pox",
      "activation_burnchain_block_height": 100,
      "first_reward_cycle_id": 0
    },
    {
      "contract_id": "ST000000000000000000002AMW42H.pox-2",
      "activation_burnchain_block_height": 110,
      "first_reward_cycle_id": 2
    }
  ]
}

Will close the issue, thanks @jcnelson!

blockstack-devops commented 3 weeks ago

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.