[Consensus] Fix testing framework concurrency and improve logging

Makefile

@@ -2,14 +2,6 @@ include build.mk
 
 CWD ?= CURRENT_WORKING_DIRECTIONRY_NOT_SUPPLIED
 
-# This flag is useful when running the consensus unit tests. It causes the test to wait up to the
-# maximum delay specified in the source code and errors if additional unexpected messages are received.
-# For example, if the test expects to receive 5 messages within 2 seconds:
-# 	When EXTRA_MSG_FAIL = false: continue if 5 messages are received in 0.5 seconds
-# 	When EXTRA_MSG_FAIL = true: wait for another 1.5 seconds after 5 messages are received in 0.5
-#		                        seconds, and fail if any additional messages are received.
-EXTRA_MSG_FAIL ?= false
-
 # IMPROVE: Add `-shuffle=on` to the `go test` command to randomize the order in which tests are run.
 
 # An easy way to turn off verbose test output for some of the test targets. For example
@@ -313,20 +305,25 @@ test_shared: ## Run all go unit tests in the shared module
 test_consensus: ## Run all go unit tests in the consensus module
 	go test ${VERBOSE_TEST} -count=1 ./consensus/...
 
+# These tests are isolated to a single package which enables logs to be streamed in realtime. More details here: https://stackoverflow.com/a/74903989/768439
+.PHONY: test_consensus_e2e
+test_consensus_e2e: ## Run all go t2e unit tests in the consensus module w/ log streaming
+	go test ${VERBOSE_TEST} -count=1 ./consensus/e2e_tests/...
+
 .PHONY: test_consensus_concurrent_tests
 test_consensus_concurrent_tests: ## Run unit tests in the consensus module that could be prone to race conditions (#192)
-	for i in $$(seq 1 100); do go test -timeout 2s -count=1 -run ^TestTinyPacemakerTimeouts$  ./consensus/consensus_tests; done;
-	for i in $$(seq 1 100); do go test -timeout 2s -count=1 -run ^TestHotstuff4Nodes1BlockHappyPath$  ./consensus/consensus_tests; done;
-	for i in $$(seq 1 100); do go test -timeout 2s -count=1 -race -run ^TestTinyPacemakerTimeouts$  ./consensus/consensus_tests; done;
-	for i in $$(seq 1 100); do go test -timeout 2s -count=1 -race -run ^TestHotstuff4Nodes1BlockHappyPath$  ./consensus/consensus_tests; done;
+	for i in $$(seq 1 100); do go test -timeout 2s -count=1 -run ^TestPacemakerTimeoutIncreasesRound$  ./consensus/e2e_tests; done;
+	for i in $$(seq 1 100); do go test -timeout 2s -count=1 -run ^TestHotstuff4Nodes1BlockHappyPath$  ./consensus/e2e_tests; done;
+	for i in $$(seq 1 100); do go test -timeout 2s -count=1 -race -run ^TestPacemakerTimeoutIncreasesRound$  ./consensus/e2e_tests; done;
+	for i in $$(seq 1 100); do go test -timeout 2s -count=1 -race -run ^TestHotstuff4Nodes1BlockHappyPath$  ./consensus/e2e_tests; done;
 
 .PHONY: test_hotstuff
 test_hotstuff: ## Run all go unit tests related to hotstuff consensus
-	go test ${VERBOSE_TEST} ./consensus/consensus_tests -run Hotstuff -failOnExtraMessages=${EXTRA_MSG_FAIL}
+	go test ${VERBOSE_TEST} ./consensus/e2e_tests -run Hotstuff
 
 .PHONY: test_pacemaker
 test_pacemaker: ## Run all go unit tests related to the hotstuff pacemaker
-	go test ${VERBOSE_TEST} ./consensus/consensus_tests -run Pacemaker -failOnExtraMessages=${EXTRA_MSG_FAIL}
+	go test ${VERBOSE_TEST} ./consensus/e2e_tests -run Pacemaker
 
 .PHONY: test_vrf
 test_vrf: ## Run all go unit tests in the VRF library

build/config/config1.json

@@ -1,14 +1,14 @@
 {
   "root_directory": "/go/src/github.com/pocket-network",
-  "private_key": "6fd0bc54cc2dd205eaf226eebdb0451629b321f11d279013ce6fdd5a33059256b2eda2232ffb2750bf761141f70f75a03a025f65b2b2b417c7f8b3c9ca91e8e4",
+  "private_key": "c6c136d010d07d7f5e9944aa3594a10f9210dd3e26ebc1bc1516a6d957fd0df353ee26c82826694ffe1773d7b60d5f20dd9e91bdf8745544711bec5ff9c6fb4a",
   "consensus": {
     "max_mempool_bytes": 500000000,
     "pacemaker_config": {
       "timeout_msec": 5000,
       "manual": true,
       "debug_time_between_steps_msec": 1000
     },
-    "private_key": "6fd0bc54cc2dd205eaf226eebdb0451629b321f11d279013ce6fdd5a33059256b2eda2232ffb2750bf761141f70f75a03a025f65b2b2b417c7f8b3c9ca91e8e4"
+    "private_key": "c6c136d010d07d7f5e9944aa3594a10f9210dd3e26ebc1bc1516a6d957fd0df353ee26c82826694ffe1773d7b60d5f20dd9e91bdf8745544711bec5ff9c6fb4a"
   },
   "utility": {
     "max_mempool_transaction_bytes": 1073741824,
@@ -25,7 +25,7 @@
     "consensus_port": 8080,
     "use_rain_tree": true,
     "is_empty_connection_type": false,
-    "private_key": "6fd0bc54cc2dd205eaf226eebdb0451629b321f11d279013ce6fdd5a33059256b2eda2232ffb2750bf761141f70f75a03a025f65b2b2b417c7f8b3c9ca91e8e4",
+    "private_key": "c6c136d010d07d7f5e9944aa3594a10f9210dd3e26ebc1bc1516a6d957fd0df353ee26c82826694ffe1773d7b60d5f20dd9e91bdf8745544711bec5ff9c6fb4a",
     "max_mempool_count": 100000
   },
   "telemetry": {

build/config/config2.json

@@ -1,14 +1,14 @@
 {
   "root_directory": "/go/src/github.com/pocket-network",
-  "private_key": "5db3e9d97d04d6d70359de924bb02039c602080d6bf01a692bad31ad5ef93524c16043323c83ffd901a8bf7d73543814b8655aa4695f7bfb49d01926fc161cdb",
+  "private_key": "b37d3ba2f232060c41ba1177fea6008d885fcccad6826d64ee7d49f94d1dbc49a8b6be75d7551da093f788f7286c3a9cb885cfc8e52710eac5f1d5e5b4bf19b2",
   "consensus": {
     "max_mempool_bytes": 500000000,
     "pacemaker_config": {
       "timeout_msec": 5000,
       "manual": true,
       "debug_time_between_steps_msec": 1000
     },
-    "private_key": "5db3e9d97d04d6d70359de924bb02039c602080d6bf01a692bad31ad5ef93524c16043323c83ffd901a8bf7d73543814b8655aa4695f7bfb49d01926fc161cdb"
+    "private_key": "b37d3ba2f232060c41ba1177fea6008d885fcccad6826d64ee7d49f94d1dbc49a8b6be75d7551da093f788f7286c3a9cb885cfc8e52710eac5f1d5e5b4bf19b2"
   },
   "utility": {
     "max_mempool_transaction_bytes": 1073741824,
@@ -25,7 +25,7 @@
     "consensus_port": 8080,
     "use_rain_tree": true,
     "is_empty_connection_type": false,
-    "private_key": "5db3e9d97d04d6d70359de924bb02039c602080d6bf01a692bad31ad5ef93524c16043323c83ffd901a8bf7d73543814b8655aa4695f7bfb49d01926fc161cdb",
+    "private_key": "b37d3ba2f232060c41ba1177fea6008d885fcccad6826d64ee7d49f94d1dbc49a8b6be75d7551da093f788f7286c3a9cb885cfc8e52710eac5f1d5e5b4bf19b2",
     "max_mempool_count": 100000
   },
   "telemetry": {

build/config/config3.json

@@ -1,14 +1,14 @@
 {
   "root_directory": "/go/src/github.com/pocket-network",
-  "private_key": "b37d3ba2f232060c41ba1177fea6008d885fcccad6826d64ee7d49f94d1dbc49a8b6be75d7551da093f788f7286c3a9cb885cfc8e52710eac5f1d5e5b4bf19b2",
+  "private_key": "5db3e9d97d04d6d70359de924bb02039c602080d6bf01a692bad31ad5ef93524c16043323c83ffd901a8bf7d73543814b8655aa4695f7bfb49d01926fc161cdb",
   "consensus": {
     "max_mempool_bytes": 500000000,
     "pacemaker_config": {
       "timeout_msec": 5000,
       "manual": true,
       "debug_time_between_steps_msec": 1000
     },
-    "private_key": "b37d3ba2f232060c41ba1177fea6008d885fcccad6826d64ee7d49f94d1dbc49a8b6be75d7551da093f788f7286c3a9cb885cfc8e52710eac5f1d5e5b4bf19b2"
+    "private_key": "5db3e9d97d04d6d70359de924bb02039c602080d6bf01a692bad31ad5ef93524c16043323c83ffd901a8bf7d73543814b8655aa4695f7bfb49d01926fc161cdb"
   },
   "utility": {
     "max_mempool_transaction_bytes": 1073741824,
@@ -25,7 +25,7 @@
     "consensus_port": 8080,
     "use_rain_tree": true,
     "is_empty_connection_type": false,
-    "private_key": "b37d3ba2f232060c41ba1177fea6008d885fcccad6826d64ee7d49f94d1dbc49a8b6be75d7551da093f788f7286c3a9cb885cfc8e52710eac5f1d5e5b4bf19b2",
+    "private_key": "5db3e9d97d04d6d70359de924bb02039c602080d6bf01a692bad31ad5ef93524c16043323c83ffd901a8bf7d73543814b8655aa4695f7bfb49d01926fc161cdb",
     "max_mempool_count": 100000
   },
   "telemetry": {

build/config/config4.json

@@ -1,14 +1,14 @@
 {
   "root_directory": "/go/src/github.com/pocket-network",
-  "private_key": "c6c136d010d07d7f5e9944aa3594a10f9210dd3e26ebc1bc1516a6d957fd0df353ee26c82826694ffe1773d7b60d5f20dd9e91bdf8745544711bec5ff9c6fb4a",
+  "private_key": "6fd0bc54cc2dd205eaf226eebdb0451629b321f11d279013ce6fdd5a33059256b2eda2232ffb2750bf761141f70f75a03a025f65b2b2b417c7f8b3c9ca91e8e4",
   "consensus": {
     "max_mempool_bytes": 500000000,
     "pacemaker_config": {
       "timeout_msec": 5000,
       "manual": true,
       "debug_time_between_steps_msec": 1000
     },
-    "private_key": "c6c136d010d07d7f5e9944aa3594a10f9210dd3e26ebc1bc1516a6d957fd0df353ee26c82826694ffe1773d7b60d5f20dd9e91bdf8745544711bec5ff9c6fb4a"
+    "private_key": "6fd0bc54cc2dd205eaf226eebdb0451629b321f11d279013ce6fdd5a33059256b2eda2232ffb2750bf761141f70f75a03a025f65b2b2b417c7f8b3c9ca91e8e4"
   },
   "utility": {
     "max_mempool_transaction_bytes": 1073741824,
@@ -25,7 +25,7 @@
     "consensus_port": 8080,
     "use_rain_tree": true,
     "is_empty_connection_type": false,
-    "private_key": "c6c136d010d07d7f5e9944aa3594a10f9210dd3e26ebc1bc1516a6d957fd0df353ee26c82826694ffe1773d7b60d5f20dd9e91bdf8745544711bec5ff9c6fb4a",
+    "private_key": "6fd0bc54cc2dd205eaf226eebdb0451629b321f11d279013ce6fdd5a33059256b2eda2232ffb2750bf761141f70f75a03a025f65b2b2b417c7f8b3c9ca91e8e4",
     "max_mempool_count": 100000
   },
   "telemetry": {

build/config/genesis.json

@@ -57,47 +57,47 @@
   ],
   "validators": [
     {
-      "address": "6f66574e1f50f0ef72dff748c3f11b9e0e89d32a",
-      "public_key": "b2eda2232ffb2750bf761141f70f75a03a025f65b2b2b417c7f8b3c9ca91e8e4",
+      "address": "113fdb095d42d6e09327ab5b8df13fd8197a1eaf",
+      "public_key": "53ee26c82826694ffe1773d7b60d5f20dd9e91bdf8745544711bec5ff9c6fb4a",
       "chains": null,
       "generic_param": "node1.consensus:8080",
       "staked_amount": "1000000000000",
       "paused_height": -1,
       "unstaking_height": -1,
-      "output": "6f66574e1f50f0ef72dff748c3f11b9e0e89d32a",
+      "output": "113fdb095d42d6e09327ab5b8df13fd8197a1eaf",
       "actor_type": 4
     },
     {
-      "address": "67eb3f0a50ae459fecf666be0e93176e92441317",
-      "public_key": "c16043323c83ffd901a8bf7d73543814b8655aa4695f7bfb49d01926fc161cdb",
+      "address": "3f52e08c4b3b65ab7cf098d77df5bf8cedcf5f99",
+      "public_key": "a8b6be75d7551da093f788f7286c3a9cb885cfc8e52710eac5f1d5e5b4bf19b2",
       "chains": null,
       "generic_param": "node2.consensus:8080",
       "staked_amount": "1000000000000",
       "paused_height": -1,
       "unstaking_height": -1,
-      "output": "67eb3f0a50ae459fecf666be0e93176e92441317",
+      "output": "3f52e08c4b3b65ab7cf098d77df5bf8cedcf5f99",
       "actor_type": 4
     },
     {
-      "address": "3f52e08c4b3b65ab7cf098d77df5bf8cedcf5f99",
-      "public_key": "a8b6be75d7551da093f788f7286c3a9cb885cfc8e52710eac5f1d5e5b4bf19b2",
+      "address": "67eb3f0a50ae459fecf666be0e93176e92441317",
+      "public_key": "c16043323c83ffd901a8bf7d73543814b8655aa4695f7bfb49d01926fc161cdb",
       "chains": null,
       "generic_param": "node3.consensus:8080",
       "staked_amount": "1000000000000",
       "paused_height": -1,
       "unstaking_height": -1,
-      "output": "3f52e08c4b3b65ab7cf098d77df5bf8cedcf5f99",
+      "output": "67eb3f0a50ae459fecf666be0e93176e92441317",
       "actor_type": 4
     },
     {
-      "address": "113fdb095d42d6e09327ab5b8df13fd8197a1eaf",
-      "public_key": "53ee26c82826694ffe1773d7b60d5f20dd9e91bdf8745544711bec5ff9c6fb4a",
+      "address": "6f66574e1f50f0ef72dff748c3f11b9e0e89d32a",
+      "public_key": "b2eda2232ffb2750bf761141f70f75a03a025f65b2b2b417c7f8b3c9ca91e8e4",
       "chains": null,
       "generic_param": "node4.consensus:8080",
       "staked_amount": "1000000000000",
       "paused_height": -1,
       "unstaking_height": -1,
-      "output": "113fdb095d42d6e09327ab5b8df13fd8197a1eaf",
+      "output": "6f66574e1f50f0ef72dff748c3f11b9e0e89d32a",
       "actor_type": 4
     }
   ],

build/docs/CHANGELOG.md

@@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+## [0.0.0.3] - 2023-01-11
+
+- Reorder private keys so addresses (retrieved by transforming private keys) to reflect the numbering in LocalNet appropriately. The address for val1, based on config1, will have the lexicographically first address. This makes debugging easier.
+
 ## [0.0.0.2] - 2023-01-10
 
 - Removed `BaseConfig` from `configs`

build/pkeys/val1.json

@@ -1 +1 @@
-"6fd0bc54cc2dd205eaf226eebdb0451629b321f11d279013ce6fdd5a33059256b2eda2232ffb2750bf761141f70f75a03a025f65b2b2b417c7f8b3c9ca91e8e4"
+"c6c136d010d07d7f5e9944aa3594a10f9210dd3e26ebc1bc1516a6d957fd0df353ee26c82826694ffe1773d7b60d5f20dd9e91bdf8745544711bec5ff9c6fb4a"

build/pkeys/val2.json

@@ -1 +1 @@
-"5db3e9d97d04d6d70359de924bb02039c602080d6bf01a692bad31ad5ef93524c16043323c83ffd901a8bf7d73543814b8655aa4695f7bfb49d01926fc161cdb"
+"b37d3ba2f232060c41ba1177fea6008d885fcccad6826d64ee7d49f94d1dbc49a8b6be75d7551da093f788f7286c3a9cb885cfc8e52710eac5f1d5e5b4bf19b2"

build/pkeys/val3.json

@@ -1 +1 @@
-"b37d3ba2f232060c41ba1177fea6008d885fcccad6826d64ee7d49f94d1dbc49a8b6be75d7551da093f788f7286c3a9cb885cfc8e52710eac5f1d5e5b4bf19b2"
+"5db3e9d97d04d6d70359de924bb02039c602080d6bf01a692bad31ad5ef93524c16043323c83ffd901a8bf7d73543814b8655aa4695f7bfb49d01926fc161cdb"

build/pkeys/val4.json

@@ -1 +1 @@
-"c6c136d010d07d7f5e9944aa3594a10f9210dd3e26ebc1bc1516a6d957fd0df353ee26c82826694ffe1773d7b60d5f20dd9e91bdf8745544711bec5ff9c6fb4a"
+"6fd0bc54cc2dd205eaf226eebdb0451629b321f11d279013ce6fdd5a33059256b2eda2232ffb2750bf761141f70f75a03a025f65b2b2b417c7f8b3c9ca91e8e4"

consensus/block.go

@@ -1,6 +1,7 @@
 package consensus
 
 import (
+	"fmt"
 	"log"
 	"unsafe"
 
@@ -24,32 +25,43 @@ func (m *consensusModule) commitBlock(block *typesCons.Block) error {
 	return nil
 }
 
-// TODO: Add unit tests specific to block validation
-// IMPROVE: (olshansky) rename to provide clarity of operation. ValidateBasic() is typically a stateless check not stateful
-func (m *consensusModule) validateBlockBasic(block *typesCons.Block) error {
-	if block == nil && m.step != NewRound {
-		return typesCons.ErrNilBlock
+// ADDTEST: Add unit tests specific to block validation
+// IMPROVE: Rename to provide clarity of operation. ValidateBasic() is typically a stateless check not stateful
+func (m *consensusModule) isValidMessageBlock(msg *typesCons.HotstuffMessage) (bool, error) {
+	block := msg.GetBlock()
+	step := msg.GetStep()
+
+	if block == nil {
+		if step != NewRound {
+			return false, fmt.Errorf("validateBlockBasic failed - block is nil during step %s", typesCons.StepToString[m.step])
+		}
+		m.nodeLog("[DEBUG] Nil (expected) block is present during NewRound step.")
+		return true, nil
 	}
 
-	if block != nil && m.step == NewRound {
-		return typesCons.ErrBlockExists
+	if block != nil && step == NewRound {
+		return false, fmt.Errorf("validateBlockBasic failed - block is not nil during step %s", typesCons.StepToString[m.step])
 	}
 
 	if block != nil && unsafe.Sizeof(*block) > uintptr(m.genesisState.GetMaxBlockBytes()) {
-		return typesCons.ErrInvalidBlockSize(uint64(unsafe.Sizeof(*block)), m.genesisState.GetMaxBlockBytes())
+		return false, typesCons.ErrInvalidBlockSize(uint64(unsafe.Sizeof(*block)), m.genesisState.GetMaxBlockBytes())
 	}
 
 	// If the current block being processed (i.e. voted on) by consensus is non nil, we need to make
 	// sure that the data (height, round, step, txs, etc) is the same before we start validating the signatures
 	if m.block != nil {
+		if m.block.BlockHeader.Hash != block.BlockHeader.Hash {
+			return false, fmt.Errorf("validateBlockBasic failed - block hash is not the same as the current block being processed by consensus")
+		}
+
 		// DISCUSS: The only difference between blocks from one step to another is the QC, so we need
 		//          to determine where/how to validate this
 		if protoHash(m.block) != protoHash(block) {
-			log.Println("[TECHDEBT][ERROR] The block being processed is not the same as that received by the consensus module ")
+			log.Println("[TECHDEBT] validateBlockBasic warning - block hash is the same but serialization is not")
 		}
 	}
 
-	return nil
+	return true, nil
 }
 
 // Creates a new Utility context and clears/nullifies any previous contexts if they exist

consensus/debugging.go

@@ -8,6 +8,9 @@ import (
 )
 
 func (m *consensusModule) HandleDebugMessage(debugMessage *messaging.DebugMessage) error {
+	m.m.Lock()
+	defer m.m.Unlock()
+
 	switch debugMessage.Action {
 	case messaging.DebugMessageAction_DEBUG_CONSENSUS_RESET_TO_GENESIS:
 		m.resetToGenesis(debugMessage)
@@ -24,12 +27,11 @@ func (m *consensusModule) HandleDebugMessage(debugMessage *messaging.DebugMessag
 }
 
 func (m *consensusModule) GetNodeState() typesCons.ConsensusNodeState {
-	m.m.RLock()
-	defer m.m.RUnlock()
 	leaderId := typesCons.NodeId(0)
 	if m.leaderId != nil {
 		leaderId = *m.leaderId
 	}
+
 	return typesCons.ConsensusNodeState{
 		NodeId:   m.nodeId,
 		Height:   m.height,
@@ -67,7 +69,7 @@ func (m *consensusModule) triggerNextView(_ *messaging.DebugMessage) {
 	if currentHeight == 0 || (currentStep == Decide && m.paceMaker.IsManualMode()) {
 		m.paceMaker.NewHeight()
 	} else {
-		m.paceMaker.InterruptRound()
+		m.paceMaker.InterruptRound("manual trigger")
 	}
 
 	if m.paceMaker.IsManualMode() {

consensus/doc/CHANGELOG.md

@@ -7,6 +7,27 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+## [0.0.0.18] - 2023-01-11
+
+### Consensus - Core
+
+- Force consensus to use a "star-like" broadcast instead of "RainTree" broadcast
+- Improve logging throughout through the use of emojis and rewording certain statements
+- Slightly improve the block verification flow (renaming, minor fixes, etc…) to stabilize LocalNet
+
+### Consensus - Tests
+
+- Rename the `consensus_tests` package to `e2e_tests`
+- Internalize configuration related to `fail_on_extra_msgs` from the `Makefile` to the `consensus` module
+- Forced all tests to fail if we receive extra unexpected messages and modify tests appropriately
+- After #198, we made tests deterministic but there was a hidden bug that modified how the test utility functions because the clock would not move while we were waiting for messages. This prevented logs from streaming, tests from failing, and other issues. Tend to all related changes.
+
+### Consensus - Pacemaker
+
+- Rename `ValidateMessage` to `ShouldHandleMessage` and return a boolean
+- Pass a `reason` to `InterruptRound`
+- Improve readability of some parts of the code
+
 ## [0.0.0.17] - 2023-01-10
 
 - Updated module constructor to accept a `bus` and not a `runtimeMgr` anymore
@@ -112,7 +133,7 @@ Consensus cleanup
 
 Consensus testing
 
-- Improved mock module initialization in `consensus/consensus_tests/utils_test.go`
+- Improved mock module initialization in `consensus/e2e_tests/utils_test.go`
 
 General