mock-test Praos ThreadNet failure: unexpected message delay

[amesgen]

On current main (e9cf1ee):

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.

[nfrisby]

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

[amesgen]

I bisected this, which yields

992bce4 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]

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

[nfrisby]

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