node/node_test: improve log handling
This commit is contained in:
parent
6f06b7fd29
commit
45d417019e
|
@ -52,11 +52,14 @@ const LOCAL_P2P_PORTRANGE_START = 10100
|
||||||
const LOCAL_STATUS_PORTRANGE_START = 10200
|
const LOCAL_STATUS_PORTRANGE_START = 10200
|
||||||
const LOCAL_PUBLICWEB_PORTRANGE_START = 10300
|
const LOCAL_PUBLICWEB_PORTRANGE_START = 10300
|
||||||
|
|
||||||
var PROMETHEUS_METRIC_VALID_HEARTBEAT_RECEIVED = []byte("wormhole_p2p_broadcast_messages_received_total{type=\"valid_heartbeat\"}")
|
var PROMETHEUS_METRIC_VALID_HEARTBEAT_RECEIVED = "wormhole_p2p_broadcast_messages_received_total{type=\"valid_heartbeat\"}"
|
||||||
|
|
||||||
const WAIT_FOR_LOGS = true
|
const WAIT_FOR_LOGS = true
|
||||||
const WAIT_FOR_METRICS = false
|
const WAIT_FOR_METRICS = false
|
||||||
|
|
||||||
|
// The level at which logs will be written to console; During testing, logs are produced and buffered at Debug level, because some tests need to look for certain entries.
|
||||||
|
const CONSOLE_LOG_LEVEL = zap.InfoLevel
|
||||||
|
|
||||||
type mockGuardian struct {
|
type mockGuardian struct {
|
||||||
p2pKey libp2p_crypto.PrivKey
|
p2pKey libp2p_crypto.PrivKey
|
||||||
MockObservationC chan *common.MessagePublication
|
MockObservationC chan *common.MessagePublication
|
||||||
|
@ -197,17 +200,15 @@ func mockGuardianRunnable(gs []*mockGuardian, mockGuardianIndex uint, obsDb mock
|
||||||
|
|
||||||
// setupLogsCapture is a helper function for making a zap logger/observer combination for testing that certain logs have been made
|
// setupLogsCapture is a helper function for making a zap logger/observer combination for testing that certain logs have been made
|
||||||
func setupLogsCapture(options ...zap.Option) (*zap.Logger, *observer.ObservedLogs) {
|
func setupLogsCapture(options ...zap.Option) (*zap.Logger, *observer.ObservedLogs) {
|
||||||
observedCore, logs := observer.New(zap.DebugLevel)
|
observedCore, observedLogs := observer.New(zap.DebugLevel)
|
||||||
wcOpt := zap.WrapCore(func(c zapcore.Core) zapcore.Core { return zapcore.NewTee(c, observedCore) })
|
consoleLogger, _ := zap.NewDevelopment(zap.IncreaseLevel(CONSOLE_LOG_LEVEL))
|
||||||
options = append(options, wcOpt)
|
parentLogger := zap.New(zapcore.NewTee(observedCore, consoleLogger.Core()), options...)
|
||||||
logger, _ := zap.NewDevelopment(options...)
|
return parentLogger, observedLogs
|
||||||
return logger, logs
|
|
||||||
}
|
}
|
||||||
|
|
||||||
func waitForHeartbeatsInLogs(t *testing.T, zapObserver *observer.ObservedLogs, gs []*mockGuardian) {
|
func waitForHeartbeatsInLogs(t testing.TB, zapObserver *observer.ObservedLogs, gs []*mockGuardian) {
|
||||||
// example log entry that we're looking for:
|
// example log entry that we're looking for:
|
||||||
// DEBUG root.g-2.g.p2p p2p/p2p.go:465 valid signed heartbeat received {"value": "node_name:\"g-0\" timestamp:1685677055425243683 version:\"development\" guardian_addr:\"0xeF2a03eAec928DD0EEAf35aD31e34d2b53152c07\" boot_timestamp:1685677040424855922 p2p_node_id:\"\\x00$\\x08\\x01\\x12 \\x97\\xf3\\xbd\\x87\\x13\\x15(\\x1e\\x8b\\x83\\xedǩ\\xfd\\x05A\\x06aTD\\x90p\\xcc\\xdb<\\xddB\\xcfi\\xccވ\"", "from": "12D3KooWL3XJ9EMCyZvmmGXL2LMiVBtrVa2BuESsJiXkSj7333Jw"}
|
// DEBUG root.g-2.g.p2p p2p/p2p.go:465 valid signed heartbeat received {"value": "node_name:\"g-0\" timestamp:1685677055425243683 version:\"development\" guardian_addr:\"0xeF2a03eAec928DD0EEAf35aD31e34d2b53152c07\" boot_timestamp:1685677040424855922 p2p_node_id:\"\\x00$\\x08\\x01\\x12 \\x97\\xf3\\xbd\\x87\\x13\\x15(\\x1e\\x8b\\x83\\xedǩ\\xfd\\x05A\\x06aTD\\x90p\\xcc\\xdb<\\xddB\\xcfi\\xccވ\"", "from": "12D3KooWL3XJ9EMCyZvmmGXL2LMiVBtrVa2BuESsJiXkSj7333Jw"}
|
||||||
// TODO maybe instead of looking at log entries, we could determine this status through prometheus metrics, which might be more stable
|
|
||||||
re := regexp.MustCompile("g-[0-9]+")
|
re := regexp.MustCompile("g-[0-9]+")
|
||||||
|
|
||||||
for readyCounter := 0; readyCounter < len(gs); {
|
for readyCounter := 0; readyCounter < len(gs); {
|
||||||
|
@ -234,7 +235,12 @@ func waitForHeartbeatsInLogs(t *testing.T, zapObserver *observer.ObservedLogs, g
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
func waitForHeartbeatsInMetrics(t *testing.T, ctx context.Context, gs []*mockGuardian) {
|
// waitForPromMetricExceed waits until prometheus metric `metric` >= `min` on all guardians in `gs`.
|
||||||
|
// WARNING: Currently, there is only a global registry for all prometheus metrics, leading to all guardian nodes writing to the same one.
|
||||||
|
//
|
||||||
|
// As long as this is the case, you probably don't want to use this function.
|
||||||
|
func waitForPromMetricGte(t testing.TB, ctx context.Context, gs []*mockGuardian, metric string, min int) {
|
||||||
|
metricBytes := []byte(metric)
|
||||||
requests := make([]*http.Request, len(gs))
|
requests := make([]*http.Request, len(gs))
|
||||||
//logger := supervisor.Logger(ctx)
|
//logger := supervisor.Logger(ctx)
|
||||||
|
|
||||||
|
@ -268,10 +274,10 @@ func waitForHeartbeatsInMetrics(t *testing.T, ctx context.Context, gs []*mockGua
|
||||||
scanner := bufio.NewScanner(resp.Body)
|
scanner := bufio.NewScanner(resp.Body)
|
||||||
for scanner.Scan() {
|
for scanner.Scan() {
|
||||||
line := scanner.Bytes()
|
line := scanner.Bytes()
|
||||||
if bytes.HasPrefix(line, PROMETHEUS_METRIC_VALID_HEARTBEAT_RECEIVED) {
|
if bytes.HasPrefix(line, metricBytes) {
|
||||||
res, err := strconv.Atoi(string(bytes.Split(line, []byte(" "))[1])) // split at the space and convert to integer
|
res, err := strconv.Atoi(string(bytes.Split(line, []byte(" "))[1])) // split at the space and convert to integer
|
||||||
assert.NoError(t, err)
|
assert.NoError(t, err)
|
||||||
if res > 0 {
|
if res >= min {
|
||||||
return true
|
return true
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
@ -569,8 +575,9 @@ func testConsensus(t *testing.T, testCases []testCase, numGuardians int) {
|
||||||
// Wait for them to connect each other and receive at least one heartbeat.
|
// Wait for them to connect each other and receive at least one heartbeat.
|
||||||
// This is necessary because if they have not joined the p2p network yet, gossip messages may get dropped silently.
|
// This is necessary because if they have not joined the p2p network yet, gossip messages may get dropped silently.
|
||||||
assert.True(t, WAIT_FOR_LOGS || WAIT_FOR_METRICS)
|
assert.True(t, WAIT_FOR_LOGS || WAIT_FOR_METRICS)
|
||||||
|
assert.False(t, WAIT_FOR_LOGS && WAIT_FOR_METRICS) // can't do both, because they both write to gs[].ready
|
||||||
if WAIT_FOR_METRICS {
|
if WAIT_FOR_METRICS {
|
||||||
waitForHeartbeatsInMetrics(t, ctx, gs)
|
waitForPromMetricGte(t, ctx, gs, PROMETHEUS_METRIC_VALID_HEARTBEAT_RECEIVED, 1)
|
||||||
}
|
}
|
||||||
if WAIT_FOR_LOGS {
|
if WAIT_FOR_LOGS {
|
||||||
waitForHeartbeatsInLogs(t, zapObserver, gs)
|
waitForHeartbeatsInLogs(t, zapObserver, gs)
|
||||||
|
|
Loading…
Reference in New Issue