ouroboros-consensus icon indicating copy to clipboard operation
ouroboros-consensus copied to clipboard

`mock-test` Praos ThreadNet failure: unexpected message delay

Open amesgen opened this issue 1 year ago • 4 comments

On current main (e9cf1eeb8afce0d44ab4a1284ad8c065a74673a3):

cabal run ouroboros-consensus-diffusion:mock-test -- --quickcheck-replay=730769 -p '/Praos.simple convergence/'

yields

Unexpected message delay (recipient: c3,expected receive slot: 55,actual receive slot: 57,blockHash: "733e4ef0280b4c01",blockNo: 37)
Full log
ouroboros-consensus
  Praos
    simple convergence: FAIL (0.86s)
      *** Failed! Falsified (after 1 test):
      TestSetup {setupEpochSize = EpochSize 1, setupInitialNonce = 1790524992889620833, setupK = SecurityParam 5, setupNodeJoinPlan = NodeJoinPlan (fromList [(CoreNodeId 0,SlotNo 9),(CoreNodeId 1,SlotNo 28),(CoreNodeId 2,SlotNo 37),(CoreNodeId 3,SlotNo 49),(CoreNodeId 4,SlotNo 56)]), setupSlotLength = SlotLength 10.277s, setupTestConfig = TestConfig {initSeed = Seed 1060741973874285844, nodeTopology = NodeTopology (fromList [(CoreNodeId 0,fromList []),(CoreNodeId 1,fromList [CoreNodeId 0]),(CoreNodeId 2,fromList [CoreNodeId 0,CoreNodeId 1]),(CoreNodeId 3,fromList [CoreNodeId 1]),(CoreNodeId 4,fromList [CoreNodeId 0,CoreNodeId 2,CoreNodeId 3])]), numCoreNodes = NumCoreNodes 5, numSlots = NumSlots 75}, setupEvolvingStake = PraosEvolvingStake (fromList [(EpochNo 0,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 2),(CoreNodeId 1,1 % 2),(CoreNodeId 2,0 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,0 % 1)]}),(EpochNo 3,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,1 % 3),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 3),(CoreNodeId 4,1 % 3)]}),(EpochNo 4,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,1 % 4),(CoreNodeId 2,1 % 4),(CoreNodeId 3,1 % 4),(CoreNodeId 4,1 % 4)]}),(EpochNo 5,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 3),(CoreNodeId 1,0 % 1),(CoreNodeId 2,1 % 3),(CoreNodeId 3,1 % 3),(CoreNodeId 4,0 % 1)]}),(EpochNo 8,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,0 % 1),(CoreNodeId 2,1 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,0 % 1)]}),(EpochNo 10,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 3),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 3),(CoreNodeId 4,1 % 3)]}),(EpochNo 13,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 2),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 2),(CoreNodeId 4,0 % 1)]}),(EpochNo 16,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,0 % 1),(CoreNodeId 2,1 % 2),(CoreNodeId 3,0 % 1),(CoreNodeId 4,1 % 2)]}),(EpochNo 18,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 2),(CoreNodeId 1,1 % 4),(CoreNodeId 2,1 % 4),(CoreNodeId 3,0 % 1),(CoreNodeId 4,0 % 1)]}),(EpochNo 19,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 4),(CoreNodeId 1,1 % 4),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 4),(CoreNodeId 4,1 % 4)]}),(EpochNo 20,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 3),(CoreNodeId 1,0 % 1),(CoreNodeId 2,1 % 3),(CoreNodeId 3,0 % 1),(CoreNodeId 4,1 % 3)]}),(EpochNo 21,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 3),(CoreNodeId 1,1 % 3),(CoreNodeId 2,0 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,1 % 3)]}),(EpochNo 27,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 4),(CoreNodeId 1,0 % 1),(CoreNodeId 2,1 % 4),(CoreNodeId 3,1 % 4),(CoreNodeId 4,1 % 4)]}),(EpochNo 31,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,1 % 3),(CoreNodeId 2,1 % 3),(CoreNodeId 3,1 % 3),(CoreNodeId 4,0 % 1)]}),(EpochNo 32,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,1 % 1)]}),(EpochNo 33,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 2),(CoreNodeId 1,0 % 1),(CoreNodeId 2,1 % 2),(CoreNodeId 3,0 % 1),(CoreNodeId 4,0 % 1)]}),(EpochNo 34,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 3),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 3),(CoreNodeId 4,1 % 3)]}),(EpochNo 35,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,1 % 2),(CoreNodeId 2,1 % 2),(CoreNodeId 3,0 % 1),(CoreNodeId 4,0 % 1)]}),(EpochNo 37,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 4),(CoreNodeId 1,1 % 4),(CoreNodeId 2,1 % 4),(CoreNodeId 3,0 % 1),(CoreNodeId 4,1 % 4)]}),(EpochNo 38,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 2),(CoreNodeId 4,1 % 2)]}),(EpochNo 40,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 4),(CoreNodeId 1,1 % 4),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 4),(CoreNodeId 4,1 % 4)]}),(EpochNo 41,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 1),(CoreNodeId 4,0 % 1)]}),(EpochNo 42,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,1 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,0 % 1)]}),(EpochNo 43,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 2),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 2),(CoreNodeId 4,0 % 1)]}),(EpochNo 44,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 3),(CoreNodeId 1,1 % 3),(CoreNodeId 2,0 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,1 % 3)]}),(EpochNo 46,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 3),(CoreNodeId 1,0 % 1),(CoreNodeId 2,1 % 3),(CoreNodeId 3,1 % 3),(CoreNodeId 4,0 % 1)]}),(EpochNo 51,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 2),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 2),(CoreNodeId 4,0 % 1)]}),(EpochNo 53,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 2),(CoreNodeId 4,1 % 2)]}),(EpochNo 54,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 1),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,0 % 1)]}),(EpochNo 57,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 5),(CoreNodeId 1,1 % 5),(CoreNodeId 2,1 % 5),(CoreNodeId 3,1 % 5),(CoreNodeId 4,1 % 5)]}),(EpochNo 61,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 1),(CoreNodeId 4,0 % 1)]}),(EpochNo 63,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,1 % 2),(CoreNodeId 2,0 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,1 % 2)]}),(EpochNo 64,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,1 % 4),(CoreNodeId 2,1 % 4),(CoreNodeId 3,1 % 4),(CoreNodeId 4,1 % 4)]}),(EpochNo 65,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 4),(CoreNodeId 1,1 % 4),(CoreNodeId 2,1 % 4),(CoreNodeId 3,1 % 4),(CoreNodeId 4,0 % 1)]}),(EpochNo 66,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,1 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,0 % 1)]}),(EpochNo 68,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 3),(CoreNodeId 1,1 % 3),(CoreNodeId 2,0 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,1 % 3)]}),(EpochNo 69,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,0 % 1),(CoreNodeId 2,1 % 3),(CoreNodeId 3,1 % 3),(CoreNodeId 4,1 % 3)]}),(EpochNo 70,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 3),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 3),(CoreNodeId 4,1 % 3)]}),(EpochNo 71,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,0 % 1),(CoreNodeId 1,0 % 1),(CoreNodeId 2,0 % 1),(CoreNodeId 3,1 % 2),(CoreNodeId 4,1 % 2)]}),(EpochNo 72,StakeDist {stakeDistToMap = fromList [(CoreNodeId 0,1 % 3),(CoreNodeId 1,1 % 3),(CoreNodeId 2,0 % 1),(CoreNodeId 3,0 % 1),(CoreNodeId 4,1 % 3)]})])}
      digraph {
          0 [label="0 "];
          1 [label="74 0 [0]"];
          2 [label="49 0"];
          3 [label="16 0"];
          4 [label="65 1"];
          5 [label="73 1"];
          6 [label="74 1 [1 2]"];
          7 [label="50 2"];
          8 [label="57 0"];
          9 [label="64 1"];
          10 [label="66 0"];
          11 [label="59 3"];
          12 [label="68 1"];
          13 [label="73 0"];
          14 [label="35 0"];
          15 [label="45 1"];
          16 [label="63 3"];
          17 [label="43 1"];
          18 [label="64 4"];
          19 [label="50 0"];
          20 [label="74 4 [3 4]"];
          21 [label="12 0"];
          22 [label="70 2"];
          23 [label="26 0"];
          24 [label="37 1"];
          25 [label="62 3"];
          26 [label="31 0"];
          27 [label="66 1"];
          28 [label="13 0"];
          29 [label="36 1"];
          30 [label="30 0"];
          31 [label="47 0"];
          32 [label="55 0"];
          33 [label="15 0"];
          34 [label="61 1"];
          35 [label="41 1"];
          36 [label="19 0"];
          37 [label="28 0"];
          38 [label="47 2"];
          39 [label="53 0"];
          40 [label="14 0"];
          41 [label="48 0"];
          42 [label="21 0"];
          43 [label="56 0"];
          44 [label="69 1"];
          45 [label="58 1"];
          46 [label="29 0"];
          47 [label="27 0"];
          48 [label="51 0"];
          49 [label="60 1"];
          50 [label="65 4"];
          51 [label="71 4"];
          52 [label="59 1"];
          53 [label="24 0"];
          54 [label="49 2"];
          55 [label="20 0"];
          56 [label="48 2"];
          57 [label="34 0"];
          58 [label="58 3"];
          59 [label="51 2"];
          60 [label="52 0"];
          61 [label="46 1"];
          62 [label="73 4"];
          63 [label="23 0"];
          64 [label="67 1"];
          65 [label="22 0"];
          66 [label="38 1"];
          67 [label="45 0"];
          68 [label="11 0"];
          69 [label="61 3"];
          70 [label="25 0"];
          71 [label="70 4"];
          72 [label="44 0"];
          73 [label="69 4"];
          74 [label="60 3"];
          75 [label="72 4"];
          76 [label="32 1"];
          77 [label="46 0"];
          1 -> 13 [label=""];
          2 -> 41 [label=""];
          3 -> 33 [label=""];
          4 -> 9 [label=""];
          5 -> 22 [label=""];
          6 -> 5 [label=""];
          7 -> 54 [label=""];
          8 -> 43 [label=""];
          9 -> 34 [label=""];
          10 -> 50 [label=""];
          11 -> 58 [label=""];
          12 -> 64 [label=""];
          13 -> 75 [label=""];
          14 -> 57 [label=""];
          15 -> 72 [label=""];
          16 -> 25 [label=""];
          17 -> 35 [label=""];
          18 -> 16 [label=""];
          19 -> 2 [label=""];
          20 -> 62 [label=""];
          21 -> 68 [label=""];
          22 -> 44 [label=""];
          23 -> 70 [label=""];
          24 -> 29 [label=""];
          25 -> 69 [label=""];
          26 -> 30 [label=""];
          27 -> 4 [label=""];
          28 -> 21 [label=""];
          29 -> 14 [label=""];
          30 -> 46 [label=""];
          31 -> 77 [label=""];
          32 -> 39 [label=""];
          33 -> 40 [label=""];
          34 -> 49 [label=""];
          35 -> 66 [label=""];
          36 -> 3 [label=""];
          37 -> 47 [label=""];
          38 -> 61 [label=""];
          39 -> 60 [label=""];
          40 -> 28 [label=""];
          41 -> 31 [label=""];
          42 -> 55 [label=""];
          43 -> 32 [label=""];
          44 -> 12 [label=""];
          45 -> 59 [label=""];
          46 -> 37 [label=""];
          47 -> 23 [label=""];
          48 -> 19 [label=""];
          49 -> 52 [label=""];
          50 -> 18 [label=""];
          51 -> 71 [label=""];
          52 -> 45 [label=""];
          53 -> 63 [label=""];
          54 -> 56 [label=""];
          55 -> 36 [label=""];
          56 -> 38 [label=""];
          57 -> 76 [label=""];
          58 -> 8 [label=""];
          59 -> 7 [label=""];
          60 -> 48 [label=""];
          61 -> 15 [label=""];
          62 -> 75 [label=""];
          63 -> 65 [label=""];
          64 -> 27 [label=""];
          65 -> 42 [label=""];
          66 -> 24 [label=""];
          67 -> 72 [label=""];
          68 -> 0 [label=""];
          69 -> 74 [label=""];
          70 -> 53 [label=""];
          71 -> 73 [label=""];
          72 -> 17 [label=""];
          73 -> 10 [label=""];
          74 -> 11 [label=""];
          75 -> 51 [label=""];
          76 -> 26 [label=""];
          77 -> 67 [label=""];
      }
      nodeChains:
        (c0,b54-s74-h"072f170487788585")
        (c1,b47-s74-h"21b42289e879aa81")
        (c2,b47-s74-h"21b42289e879aa81")
        (c3,b54-s74-h"5403f7cacf31fa2c")
        (c4,b54-s74-h"5403f7cacf31fa2c")

      nodeJoinPlan: [(c0,9),(c1,28),(c2,37),(c3,49),(c4,56)]
      nodeRestarts: []
      nodeTopology: [(c0,[]),(c1,[c0]),(c2,[c0,c1]),(c3,[c1]),(c4,[c0,c2,c3])]
      slot-node-tipBlockNo: [(9,[(c0,origin)]),(10,[(c0,origin)]),(11,[(c0,origin)]),(12,[(c0,0)]),(13,[(c0,1)]),(14,[(c0,2)]),(15,[(c0,3)]),(16,[(c0,4)]),(17,[(c0,5)]),(18,[(c0,5)]),(19,[(c0,5)]),(20,[(c0,6)]),(21,[(c0,7)]),(22,[(c0,8)]),(23,[(c0,9)]),(24,[(c0,10)]),(25,[(c0,11)]),(26,[(c0,12)]),(27,[(c0,13)]),(28,[(c0,14),(c1,origin)]),(29,[(c0,15),(c1,15)]),(30,[(c0,16),(c1,16)]),(31,[(c0,17),(c1,17)]),(32,[(c0,18),(c1,18)]),(33,[(c0,19),(c1,19)]),(34,[(c0,19),(c1,19)]),(35,[(c0,20),(c1,20)]),(36,[(c0,21),(c1,21)]),(37,[(c0,22),(c1,22),(c2,origin)]),(38,[(c0,23),(c1,23),(c2,23)]),(39,[(c0,24),(c1,24),(c2,24)]),(40,[(c0,24),(c1,24),(c2,24)]),(41,[(c0,24),(c1,24),(c2,24)]),(42,[(c0,25),(c1,25),(c2,25)]),(43,[(c0,25),(c1,25),(c2,25)]),(44,[(c0,26),(c1,26),(c2,26)]),(45,[(c0,27),(c1,27),(c2,27)]),(46,[(c0,28),(c1,28),(c2,28)]),(47,[(c0,29),(c1,29),(c2,29)]),(48,[(c0,30),(c1,30),(c2,30)]),(49,[(c0,31),(c1,31),(c2,31),(c3,origin)]),(50,[(c0,32),(c1,32),(c2,32),(c3,32)]),(51,[(c0,33),(c1,33),(c2,33),(c3,33)]),(52,[(c0,34),(c1,34),(c2,34),(c3,34)]),(53,[(c0,35),(c1,34),(c2,34),(c3,35)]),(54,[(c0,36),(c1,34),(c2,34),(c3,36)]),(55,[(c0,36),(c1,34),(c2,34),(c3,37)]),(56,[(c0,37),(c1,34),(c2,34),(c3,37),(c4,origin)]),(57,[(c0,38),(c1,34),(c2,34),(c3,37),(c4,38)]),(58,[(c0,39),(c1,34),(c2,34),(c3,39),(c4,39)]),(59,[(c0,40),(c1,35),(c2,35),(c3,40),(c4,40)]),(60,[(c0,41),(c1,36),(c2,36),(c3,41),(c4,41)]),(61,[(c0,42),(c1,37),(c2,37),(c3,42),(c4,42)]),(62,[(c0,43),(c1,38),(c2,38),(c3,43),(c4,43)]),(63,[(c0,44),(c1,38),(c2,38),(c3,44),(c4,44)]),(64,[(c0,45),(c1,38),(c2,38),(c3,45),(c4,45)]),(65,[(c0,46),(c1,39),(c2,39),(c3,46),(c4,46)]),(66,[(c0,47),(c1,40),(c2,40),(c3,47),(c4,47)]),(67,[(c0,48),(c1,41),(c2,41),(c3,48),(c4,48)]),(68,[(c0,48),(c1,42),(c2,42),(c3,48),(c4,48)]),(69,[(c0,48),(c1,43),(c2,43),(c3,48),(c4,48)]),(70,[(c0,49),(c1,44),(c2,44),(c3,49),(c4,49)]),(71,[(c0,50),(c1,45),(c2,45),(c3,50),(c4,50)]),(72,[(c0,51),(c1,45),(c2,45),(c3,51),(c4,51)]),(73,[(c0,52),(c1,45),(c2,45),(c3,52),(c4,52)]),(74,[(c0,53),(c1,46),(c2,46),(c3,53),(c4,53)])]
      mbSchedule: Nothing
      growth schedule: [(0,[]),(1,[]),(2,[]),(3,[]),(4,[]),(5,[]),(6,[]),(7,[]),(8,[]),(9,[]),(10,[]),(11,[c0]),(12,[c0]),(13,[c0]),(14,[c0]),(15,[c0]),(16,[c0]),(17,[]),(18,[]),(19,[c0]),(20,[c0]),(21,[c0]),(22,[c0]),(23,[c0]),(24,[c0]),(25,[c0]),(26,[c0]),(27,[c0]),(28,[c0]),(29,[c0]),(30,[c0]),(31,[c0]),(32,[c1]),(33,[]),(34,[c0]),(35,[c0]),(36,[c1]),(37,[c1]),(38,[c0,c1,c2]),(39,[]),(40,[]),(41,[c0,c1]),(42,[]),(43,[c1]),(44,[c0]),(45,[c0,c1]),(46,[c0,c1]),(47,[c0,c2]),(48,[c0,c2]),(49,[c0,c2]),(50,[c0,c2,c3]),(51,[c0,c2,c3]),(52,[c0,c3]),(53,[c0,c3]),(54,[c3]),(55,[c0]),(56,[c0]),(57,[c0]),(58,[c0,c1,c2,c3,c4]),(59,[c0,c1,c2,c3,c4]),(60,[c0,c1,c2,c3,c4]),(61,[c0,c1,c2,c3,c4]),(62,[c3]),(63,[c3]),(64,[c1,c4]),(65,[c1,c2,c3,c4]),(66,[c0,c1,c2,c3]),(67,[c1]),(68,[c1]),(69,[c0,c1,c4]),(70,[c2,c3,c4]),(71,[c0,c3,c4]),(72,[c3,c4]),(73,[c0,c1,c4]),(74,[c0,c1,c4])]
      actual leader schedule: [(0,[]),(1,[]),(2,[]),(3,[]),(4,[]),(5,[]),(6,[]),(7,[]),(8,[]),(9,[]),(10,[]),(11,[c0]),(12,[c0]),(13,[c0]),(14,[c0]),(15,[c0]),(16,[c0]),(17,[]),(18,[]),(19,[c0]),(20,[c0]),(21,[c0]),(22,[c0]),(23,[c0]),(24,[c0]),(25,[c0]),(26,[c0]),(27,[c0]),(28,[c0]),(29,[c0]),(30,[c0]),(31,[c0]),(32,[c1]),(33,[]),(34,[c0]),(35,[c0]),(36,[c1]),(37,[c1,c2]),(38,[c0,c1,c2]),(39,[]),(40,[]),(41,[c0,c1]),(42,[]),(43,[c1]),(44,[c0]),(45,[c0,c1]),(46,[c0,c1]),(47,[c0,c2]),(48,[c0,c2]),(49,[c0,c2,c3]),(50,[c0,c2,c3]),(51,[c0,c2,c3]),(52,[c0,c3]),(53,[c0,c3]),(54,[c3]),(55,[c0]),(56,[c0]),(57,[c0]),(58,[c0,c1,c2,c3,c4]),(59,[c0,c1,c2,c3,c4]),(60,[c0,c1,c2,c3,c4]),(61,[c0,c1,c2,c3,c4]),(62,[c3]),(63,[c3]),(64,[c1,c4]),(65,[c1,c2,c3,c4]),(66,[c0,c1,c2,c3]),(67,[c1]),(68,[c1]),(69,[c0,c1,c4]),(70,[c2,c3,c4]),(71,[c0,c3,c4]),(72,[c3,c4]),(73,[c0,c1,c4]),(74,[c0,c1,c4])]
      consensus expected: False
      maxForkLength: 30
      Unexpected message delay (recipient: c3,expected receive slot: 55,actual receive slot: 57,blockHash: "733e4ef0280b4c01",blockNo: 37)
      Use --quickcheck-replay=730769 to reproduce.

amesgen avatar May 16 '24 09:05 amesgen

The slot-node-tipBlockNo and actual leader schedule includes:

  • (53,[(c0,35),(c1,34),(c2,34),(c3,35)]) -- (53,[c0,c3])
  • (54,[(c0,36),(c1,34),(c2,34),(c3,36)]) -- (54,[c3])
  • (55,[(c0,36),(c1,34),(c2,34),(c3,37)]) -- (55,[c0])
  • (56,[(c0,37),(c1,34),(c2,34),(c3,37),(c4,origin)]) -- (56,[c0])
  • (57,[(c0,38),(c1,34),(c2,34),(c3,37),(c4,38)])

So it looks like c0 and c3 both forged their own block 36. Then c3 forged its 37 and then in the next slot c0 forged its 37.

Maybe c0 forged 733e4ef0280b4c01 and the test logic thought that won the tiebreaker but it didn't actually in the test (😕)? Then when c0 mints again in 56, c3 finally does switch (selecting 733...) due to the chain being longer.

🤷 just one idea

nfrisby avatar May 17 '24 00:05 nfrisby

I bisected this, which yields

992bce4af032f0c07196acdc06e38dd6d0cc10c0 is the first bad commit

ie #332. That is rather surprising to me. I wondered whether any changes in the generators could be responsible for this, but the cabal-plan diff output looks quite innocent:

Package versions
~~~~~~~~~~~~~~~~

-cardano-ledger-conway-1.7.0.0 lib
+cardano-ledger-conway-1.7.1.0 lib
-cardano-ledger-conway-1.7.0.0 lib:testlib
+cardano-ledger-conway-1.7.1.0 lib:testlib
-cardano-ledger-shelley-1.5.0.0 lib
+cardano-ledger-shelley-1.5.1.0 lib
-cardano-ledger-shelley-1.5.0.0 lib:testlib
+cardano-ledger-shelley-1.5.1.0 lib:testlib
-strict-checked-vars-0.1.0.3 lib
+strict-checked-vars-0.1.0.4 lib

Next step might be to revert some of the "SVar -> MVar" changes and see if they are responsible.


Bisection details
git bisect start '--first-parent'
# status: waiting for both good and bad commits
# good: [6eedbf28dd5127577eb07752a3949e15d4345639] Nixify
git bisect good 6eedbf28dd5127577eb07752a3949e15d4345639
# status: waiting for bad commit, 1 good commit known
# bad: [e9cf1eeb8afce0d44ab4a1284ad8c065a74673a3] Bump cachix/install-nix-action from 26 to 27 (#1104)
git bisect bad e9cf1eeb8afce0d44ab4a1284ad8c065a74673a3

bisect.sh:

#!/usr/bin/env bash
set -e

nix build .#hydraJobs.x86_64-linux.native.haskell96.tests.ouroboros-consensus-diffusion.mock-test \
    || nix build .#hydraJobs.x86_64-linux.native.haskell810.tests.ouroboros-consensus-diffusion.mock-test \
    || nix build .#hydraJobs.x86_64-linux.native.haskell.tests.ouroboros-consensus-diffusion.mock-test \
    || nix build .#hydraJobs.x86_64-linux.native.tests.ouroboros-consensus-diffusion.mock-test \
    || exit 127

result/bin/mock-test -p '/Praos.simple convergence/' --quickcheck-replay=730769
result/bin/mock-test -p '/Praos.simple convergence/' --quickcheck-tests=20000

amesgen avatar May 21 '24 09:05 amesgen

Reverting the changes to ouroboros-consensus/src/ouroboros-consensus/Ouroboros/Consensus/Storage/ImmutableDB/Impl/Index/Cache.hs in #332 on top of 992bce4af032f0c07196acdc06e38dd6d0cc10c0 fixes the test failure, but the test is still failing when applying the same patch on top of current main (e9cf1eeb8afce0d44ab4a1284ad8c065a74673a3). My suspicion is that the exact STM schedule is relevant here, so #332 might be a red herring.

amesgen avatar May 21 '24 11:05 amesgen

My rough summary from our call.

  • What is now called SVar used to be called MVar, and so was mistakenly used in several places where Consensus merely wanted to use an actual MVar. That's what Joris' PR fixed (by renaming it and fixing up the now-obviously-confused imports).
  • The SVar has the same semantics as an TMVar unless you use a special function --- which the accidental uses didn't use.
  • So Joris' fix effectively replaces TMVars with MVars. That's enough to change the io-sim scheduler decisions, especially since (as Joris mentioned) io-sim tries to give MVar uses some fairness.
  • Thus that plausibly explains why that patch affects this test case: it changes the pattern of variable reads/writes, and so alters the scheduling.
  • But we still don't know why it would fail. There's a bug somewhere: our two suspects are the failing ThreadNet predicate doesn't account for a rare race condition outcome or the io-sim scheduler has a bug (eg time advances even when some thread is (imminently) unblocked).

cc @amesgen @jorisdral

nfrisby avatar May 23 '24 15:05 nfrisby