From 62ddbd132ffd8c2e135f7a440f68ec9b3aa7bf10 Mon Sep 17 00:00:00 2001 From: Genady Gurevich Date: Wed, 21 Jan 2026 17:16:19 +0200 Subject: [PATCH 1/4] saving Signed-off-by: Genady Gurevich From 7aae332d46332cb7d2aba81a0548d363edb6b5c6 Mon Sep 17 00:00:00 2001 From: Genady Gurevich Date: Wed, 21 Jan 2026 17:16:19 +0200 Subject: [PATCH 2/4] saving Signed-off-by: Genady Gurevich From 4a84d1107ebab424480d0982da10d33cdcaf966b Mon Sep 17 00:00:00 2001 From: Genady Gurevich Date: Wed, 21 Jan 2026 17:16:19 +0200 Subject: [PATCH 3/4] saving Signed-off-by: Genady Gurevich From 97be911f421558e4a62cac95b611760ad2851ccb Mon Sep 17 00:00:00 2001 From: Genady Gurevich Date: Wed, 21 Jan 2026 17:16:19 +0200 Subject: [PATCH 4/4] Operations endpoints: logspec handler (issue #45) Signed-off-by: Genady Gurevich --- common/operations/system.go | 34 ++++ node/assembler/assembler.go | 1 + node/batcher/batcher.go | 1 + node/consensus/consensus.go | 4 +- node/router/router.go | 1 + test/basic/basic_test.go | 191 +++++++++++------- test/basic/router_basic_test.go | 111 +++++++--- test/faulttolerance/assembler_test.go | 103 +++++++--- test/faulttolerance/router_test.go | 5 +- testutil/network_utils.go | 86 ++++++-- .../common/flogging/httpadmin/spec.go | 83 ++++++++ vendor/modules.txt | 1 + 12 files changed, 471 insertions(+), 150 deletions(-) create mode 100644 vendor/github.com/hyperledger/fabric-lib-go/common/flogging/httpadmin/spec.go diff --git a/common/operations/system.go b/common/operations/system.go index cb471fde3..7e5aa136d 100644 --- a/common/operations/system.go +++ b/common/operations/system.go @@ -11,6 +11,7 @@ import ( "time" "github.com/hyperledger/fabric-lib-go/common/flogging" + "github.com/hyperledger/fabric-lib-go/common/flogging/httpadmin" "github.com/hyperledger/fabric-lib-go/common/metrics" "github.com/hyperledger/fabric-lib-go/healthz" "github.com/prometheus/client_golang/prometheus/promhttp" @@ -87,6 +88,10 @@ func HealthCheckServiceURL(system *System, logger *flogging.FabricLogger) string return operationServiceURL("healthz", system.Addr(), logger) } +func LogSpecServiceURL(system *System, logger *flogging.FabricLogger) string { + return operationServiceURL("logspec", system.Addr(), logger) +} + // NewOperationsSystem creates a new operations system with the provided configuration. func NewOperationsSystem(ops Operations, metricsConfig Metrics) *System { o := Options{ @@ -122,6 +127,7 @@ func NewOperationsSystem(ops Operations, metricsConfig Metrics) *System { system.initializeMetricsProvider() system.initializeHealthCheckHandler() + system.initializeLoggingHandler() return system } @@ -165,3 +171,31 @@ func (s *System) initializeHealthCheckHandler() { // description: Service unavailable. s.RegisterHandler("/healthz", s.healthHandler, false) } + +func (s *System) initializeLoggingHandler() { + // swagger:operation GET /logspec operations logspecget + // --- + // summary: Retrieves the active logging spec for a peer or orderer. + // responses: + // '200': + // description: Ok. + + // swagger:operation PUT /logspec operations logspecput + // --- + // summary: Updates the active logging spec for a peer or orderer. + // + // parameters: + // - name: payload + // in: formData + // type: string + // description: The payload must consist of a single attribute named spec. + // required: true + // responses: + // '204': + // description: No content. + // '400': + // description: Bad request. + // consumes: + // - multipart/form-data + s.RegisterHandler("/logspec", httpadmin.NewSpecHandler(), s.options.TLS.Enabled) +} diff --git a/node/assembler/assembler.go b/node/assembler/assembler.go index 241d3c15c..077c7a7cc 100644 --- a/node/assembler/assembler.go +++ b/node/assembler/assembler.go @@ -162,6 +162,7 @@ func NewDefaultAssembler( assembler.logger.Infof("Prometheus serving on URL: %s", operations.PrometheusMetricsServiceURL(assembler.opsSystem, assembler.logger)) assembler.logger.Infof("Health check serving on URL: %s", operations.HealthCheckServiceURL(assembler.opsSystem, assembler.logger)) + assembler.logger.Infof("Logging spec service serving on URL: %s", operations.LogSpecServiceURL(assembler.opsSystem, assembler.logger)) assembler.metrics.StartMetricsTracker() return assembler diff --git a/node/batcher/batcher.go b/node/batcher/batcher.go index 4d05931b0..af0ee14be 100644 --- a/node/batcher/batcher.go +++ b/node/batcher/batcher.go @@ -154,6 +154,7 @@ func (b *Batcher) Run() { b.metrics.StartMetricsTracker() b.logger.Infof("Prometheus serving on URL: %s", b.MonitoringServiceAddress()) b.logger.Infof("Health check serving on URL: %s", operations.HealthCheckServiceURL(b.opsSystem, b.logger)) + b.logger.Infof("Logging spec service serving on URL: %s", operations.LogSpecServiceURL(b.opsSystem, b.logger)) } func (b *Batcher) GetStatus() string { diff --git a/node/consensus/consensus.go b/node/consensus/consensus.go index a85a7fa5d..5a02948f5 100644 --- a/node/consensus/consensus.go +++ b/node/consensus/consensus.go @@ -134,9 +134,11 @@ func (c *Consensus) Start() error { } RegisterHealthCheckers(c) + c.Metrics.StartMetricsTracker() c.Logger.Infof("Prometheus serving on URL: %s", operations.PrometheusMetricsServiceURL(c.opsSystem, c.Logger)) c.Logger.Infof("Health check serving on URL: %s", operations.HealthCheckServiceURL(c.opsSystem, c.Logger)) - c.Metrics.StartMetricsTracker() + c.Logger.Infof("Logging spec service serving on URL: %s", operations.LogSpecServiceURL(c.opsSystem, c.Logger)) + bft := c.BFT c.lock.Unlock() diff --git a/node/router/router.go b/node/router/router.go index 826027d40..093174967 100644 --- a/node/router/router.go +++ b/node/router/router.go @@ -187,6 +187,7 @@ func (r *Router) initFromConfig(rconfig *nodeconfig.RouterNodeConfig, configurat r.metrics.StartMetricsTracker() r.logger.Infof("Prometheus serving on URL: %s", r.MonitoringServiceAddress()) r.logger.Infof("Health check serving on URL: %s", operations.HealthCheckServiceURL(r.opsSystem, r.logger)) + r.logger.Infof("Logging spec service serving on URL: %s", operations.LogSpecServiceURL(r.opsSystem, r.logger)) r.logger.Infof("Router with PartyID: %d has been initialized from config with sequence: %d", rconfig.PartyID, r.configSeq) } diff --git a/test/basic/basic_test.go b/test/basic/basic_test.go index 9b5ed162d..31b010100 100644 --- a/test/basic/basic_test.go +++ b/test/basic/basic_test.go @@ -15,6 +15,7 @@ import ( "testing" "time" + "github.com/hyperledger/fabric-lib-go/common/flogging/httpadmin" "github.com/hyperledger/fabric-protos-go-apiv2/common" "github.com/hyperledger/fabric-x-orderer/common/tools/armageddon" "github.com/hyperledger/fabric-x-orderer/common/types" @@ -286,50 +287,131 @@ func TestSubmitAndReceiveStatus(t *testing.T) { // TestRunNodesAndGetResponseFromOperationEndpoints verifies that the nodes respond correctly to operation endpoints INSECURED. // The test performs the following steps: -// 1. Creates a test network configuration -// 2. Generates network artifacts using armageddon CLI -// 3. Builds and starts the arma node binary -// 4. Sends a configurable number of transactions (10) using a rate-limited broadcast client -// 5. Monitors Prometheus metrics exposed by the batcher and consenter nodes -// 6. Checks the health check endpoints of the batcher and consenter nodes +// 1. Compile the arma binary. +// 2. Create a network with 2 parties and 1 shard. +// 3. Generate network artifacts using the arma generate command. +// 4. Run the arma nodes and wait for them to be ready. +// 5. Verify that the batcher is running and has no DEBUG logs in its output. +// 6. Verify that the consenter is running and has no DEBUG logs in its output. +// 7. Update log spec to DEBUG for both batcher and consenter, and verify the change. +// 8. Send transactions to the routers. +// 9. Verify that the batcher and consenter have DEBUG logs in their output after sending transactions. +// 10. Verify that the batcher and consenter Prometheus metrics reflect the transactions sent. +// 11. Verify that the batcher and consenter health check endpoints respond with status "OK". func TestRunNodesAndGetResponseFromOperationEndpoints(t *testing.T) { // 1. armaBinaryPath, err := gexec.BuildWithEnvironment("github.com/hyperledger/fabric-x-orderer/cmd/arma", []string{"GOPRIVATE=" + os.Getenv("GOPRIVATE")}) - defer gexec.CleanupBuildArtifacts() + t.Cleanup(func() { + gexec.CleanupBuildArtifacts() + }) require.NoError(t, err) require.NotNil(t, armaBinaryPath) - // 2. - parties := 2 + // 2. create network with 1 parties and 1 shard + parties := 1 shards := 1 t.Logf("Running test with %d parties and %d shards", parties, shards) - // Create a temporary directory for the test dir, err := os.MkdirTemp("", t.Name()) require.NoError(t, err) - defer os.RemoveAll(dir) + t.Cleanup(func() { + os.RemoveAll(dir) + }) - // 3. + // 3. create config.yaml and generate network artifacts configPath := filepath.Join(dir, "config.yaml") netInfo := testutil.CreateNetwork(t, configPath, parties, shards, "none", "none") - defer netInfo.CleanUp() + t.Cleanup(func() { + netInfo.CleanUp() + }) require.NotNil(t, netInfo) numOfArmaNodes := len(netInfo) armageddon.NewCLI().Run([]string{"generate", "--config", configPath, "--output", dir}) + // 4. run arma nodes readyChan := make(chan string, numOfArmaNodes) armaNetwork := testutil.RunArmaNodes(t, dir, armaBinaryPath, readyChan, netInfo) - defer armaNetwork.Stop() + t.Cleanup(func() { + armaNetwork.Stop() + }) testutil.WaitReady(t, readyChan, numOfArmaNodes, 10) + debugRe := regexp.MustCompile("DEBU") + + batcherToTest := armaNetwork.GetBatcher(t, types.PartyID(1), types.ShardID(1)) + + // 5. Verify that the batcher is running and has no DEBUG logs in its output + matches := debugRe.FindStringSubmatch(string(batcherToTest.RunInfo.Session.Err.Contents())) + require.Len(t, matches, 0, "expected to not find DEBUG logs in batcher output") + + batcherLogSpecURL := testutil.CaptureArmaNodeLogSpecServiceURL(t, batcherToTest) + logSpecRe := regexp.MustCompile(`^\{\s*"spec"\s*:\s*"([^"]*)"\s*\}`) + + require.Eventually(t, func() bool { + logSpec := testutil.FetchLogSpecValue(t, logSpecRe, batcherLogSpecURL) + if logSpec == nil { + return false + } + if logSpec.Spec == "info" { + return true + } + return false + }, 30*time.Second, 100*time.Millisecond) + + consenterToTest := armaNetwork.GetConsenter(t, 1) + + // 6. Verify that the consenter is running and has no DEBUG logs in its output + matches = debugRe.FindStringSubmatch(string(consenterToTest.RunInfo.Session.Err.Contents())) + require.Len(t, matches, 0, "expected to not find DEBUG logs in consenter output") + + consenterLogSpecURL := testutil.CaptureArmaNodeLogSpecServiceURL(t, consenterToTest) + + require.Eventually(t, func() bool { + logSpec := testutil.FetchLogSpecValue(t, logSpecRe, consenterLogSpecURL) + if logSpec == nil { + return false + } + if logSpec.Spec == "info" { + return true + } + return false + }, 30*time.Second, 100*time.Millisecond) + + // 7. Update log spec to DEBUG for both batcher and consenter, and verify the change + testutil.UpdateLogSpecValue(t, batcherLogSpecURL, &httpadmin.LogSpec{Spec: "debug"}) + + require.Eventually(t, func() bool { + logSpec := testutil.FetchLogSpecValue(t, logSpecRe, batcherLogSpecURL) + if logSpec == nil { + return false + } + if logSpec.Spec == "debug" { + return true + } + return false + }, 30*time.Second, 100*time.Millisecond) + + testutil.UpdateLogSpecValue(t, consenterLogSpecURL, &httpadmin.LogSpec{Spec: "debug"}) + + require.Eventually(t, func() bool { + logSpec := testutil.FetchLogSpecValue(t, logSpecRe, consenterLogSpecURL) + if logSpec == nil { + return false + } + if logSpec.Spec == "debug" { + return true + } + return false + }, 30*time.Second, 100*time.Millisecond) + uc, err := testutil.GetUserConfig(dir, 1) assert.NoError(t, err) assert.NotNil(t, uc) - // 4. + // 8. Send transactions to the routers. totalTxNumber := 10 fillInterval := 10 * time.Millisecond fillFrequency := 1000 / int(fillInterval.Milliseconds()) @@ -337,19 +419,13 @@ func TestRunNodesAndGetResponseFromOperationEndpoints(t *testing.T) { capacity := rate / fillFrequency rl, err := armageddon.NewRateLimiter(rate, fillInterval, capacity) - if err != nil { - fmt.Fprintf(os.Stderr, "failed to start a rate limiter, err: %v\n", err) - os.Exit(3) - } + require.NoError(t, err) broadcastClient := client.NewBroadcastTxClient(uc, 10*time.Second) for i := range totalTxNumber { status := rl.GetToken() - if !status { - fmt.Fprintf(os.Stderr, "failed to send tx %d", i+1) - os.Exit(3) - } + require.Truef(t, status, "failed to send tx %d", i+1) txContent := tx.PrepareTxWithTimestamp(i, 64, []byte("sessionNumber")) env := tx.CreateStructuredEnvelope(txContent) err = broadcastClient.SendTx(env) @@ -359,76 +435,43 @@ func TestRunNodesAndGetResponseFromOperationEndpoints(t *testing.T) { t.Log("Finished submit") broadcastClient.Stop() - // 5. - // Verify secondary batcher metrics. - batcherToMonitor := armaNetwork.GetBatcher(t, types.PartyID(1), types.ShardID(1)) - url := testutil.CaptureArmaNodePrometheusServiceURL(t, batcherToMonitor) - - pattern := fmt.Sprintf(`batcher_router_txs_total\{party_id="%d",shard_id="%d"\} \d+`, types.PartyID(1), types.ShardID(1)) - re := regexp.MustCompile(pattern) - - require.Eventually(t, func() bool { - return testutil.FetchPrometheusMetricValue(t, re, url) == totalTxNumber - }, 30*time.Second, 100*time.Millisecond) - - pattern = fmt.Sprintf(`batcher_batch_verify_latency_seconds_count\{party_id="%d",shard_id="%d"\} \d+`, types.PartyID(1), types.ShardID(1)) - re = regexp.MustCompile(pattern) - - require.Eventually(t, func() bool { - return testutil.FetchPrometheusMetricValue(t, re, url) > 0 - }, 30*time.Second, 100*time.Millisecond) - - pattern = fmt.Sprintf(`batcher_batch_ledger_append_latency_seconds_count\{party_id="%d",shard_id="%d"\} \d+`, types.PartyID(1), types.ShardID(1)) - re = regexp.MustCompile(pattern) - + // 9. Verify that the batcher and consenter have DEBUG logs in their output after sending transactions require.Eventually(t, func() bool { - return testutil.FetchPrometheusMetricValue(t, re, url) > 0 + matches := debugRe.FindStringSubmatch(string(batcherToTest.RunInfo.Session.Err.Contents())) + return len(matches) > 0 }, 30*time.Second, 100*time.Millisecond) - // Verify primary batcher metrics. - batcherToMonitor = armaNetwork.GetBatcher(t, types.PartyID(2), types.ShardID(1)) - url = testutil.CaptureArmaNodePrometheusServiceURL(t, batcherToMonitor) - - pattern = fmt.Sprintf(`batcher_batch_mempool_next_requests_latency_seconds_count\{party_id="%d",shard_id="%d"\} \d+`, types.PartyID(2), types.ShardID(1)) - re = regexp.MustCompile(pattern) - require.Eventually(t, func() bool { - return testutil.FetchPrometheusMetricValue(t, re, url) > 0 + matches := debugRe.FindStringSubmatch(string(consenterToTest.RunInfo.Session.Err.Contents())) + return len(matches) > 0 }, 30*time.Second, 100*time.Millisecond) - pattern = fmt.Sprintf(`batcher_batch_ledger_append_latency_seconds_count\{party_id="%d",shard_id="%d"\} \d+`, types.PartyID(2), types.ShardID(1)) - re = regexp.MustCompile(pattern) + // 10. Verify that the batcher and consenter Prometheus metrics reflect the transactions sent + batcherPrometheusURL := testutil.CaptureArmaNodePrometheusServiceURL(t, batcherToTest) + batcherPrometheusRe := regexp.MustCompile(fmt.Sprintf(`batcher_router_txs_total\{party_id="%d",shard_id="%d"\} \d+`, types.PartyID(1), types.ShardID(1))) require.Eventually(t, func() bool { - return testutil.FetchPrometheusMetricValue(t, re, url) > 0 + return testutil.FetchPrometheusMetricValue(t, batcherPrometheusRe, batcherPrometheusURL) == totalTxNumber }, 30*time.Second, 100*time.Millisecond) - consenterToMonitor := armaNetwork.GetConsenter(t, 1) - url = testutil.CaptureArmaNodePrometheusServiceURL(t, consenterToMonitor) - - pattern = fmt.Sprintf(`consensus_bafs_count\{party_id="%d"\} \d+`, types.PartyID(1)) - re = regexp.MustCompile(pattern) + consenterPrometheusURL := testutil.CaptureArmaNodePrometheusServiceURL(t, consenterToTest) + consenterPrometheusRe := regexp.MustCompile(fmt.Sprintf(`consensus_bafs_count\{party_id="%d"\} \d+`, types.PartyID(1))) require.Eventually(t, func() bool { - return testutil.FetchPrometheusMetricValue(t, re, url) >= parties*shards + return testutil.FetchPrometheusMetricValue(t, consenterPrometheusRe, consenterPrometheusURL) >= parties*shards }, 30*time.Second, 100*time.Millisecond) - // 6. - url = testutil.CaptureArmaNodeHealthCheckServiceURL(t, batcherToMonitor) - - pattern = `^\{\s*"status"\s*:\s*"([^"]+)"(?:\s*,\s*"time"\s*:\s*"[^"]*")?\s*\}$` - re = regexp.MustCompile(pattern) + // 11. Verify that the batcher and consenter health check endpoints respond with status "OK" + batcherHealthCheckURL := testutil.CaptureArmaNodeHealthCheckServiceURL(t, batcherToTest) + healthCheckRe := regexp.MustCompile(`^\{\s*"status"\s*:\s*"([^"]+)"(?:\s*,\s*"time"\s*:\s*"[^"]*")?\s*\}$`) require.Eventually(t, func() bool { - return testutil.GetHealthCheckStatus(t, re, url) + return testutil.GetHealthCheckStatus(t, healthCheckRe, batcherHealthCheckURL) }, 30*time.Second, 100*time.Millisecond) - url = testutil.CaptureArmaNodeHealthCheckServiceURL(t, consenterToMonitor) - - pattern = `^\{\s*"status"\s*:\s*"([^"]+)"(?:\s*,\s*"time"\s*:\s*"[^"]*")?\s*\}$` - re = regexp.MustCompile(pattern) + consenterHealthCheckURL := testutil.CaptureArmaNodeHealthCheckServiceURL(t, consenterToTest) require.Eventually(t, func() bool { - return testutil.GetHealthCheckStatus(t, re, url) + return testutil.GetHealthCheckStatus(t, healthCheckRe, consenterHealthCheckURL) }, 30*time.Second, 100*time.Millisecond) } diff --git a/test/basic/router_basic_test.go b/test/basic/router_basic_test.go index 4bd7d17c3..02f255149 100644 --- a/test/basic/router_basic_test.go +++ b/test/basic/router_basic_test.go @@ -16,6 +16,7 @@ import ( "testing" "time" + "github.com/hyperledger/fabric-lib-go/common/flogging/httpadmin" "github.com/hyperledger/fabric-x-orderer/common/tools/armageddon" "github.com/hyperledger/fabric-x-orderer/common/types" "github.com/hyperledger/fabric-x-orderer/common/utils" @@ -34,18 +35,24 @@ import ( // TestSubmitToRouterGetResponseFromOperationEndpoints tests the end-to-end flow of submitting transactions to the router // and verifying that the correct response is received from the operation endpoints INSECURED. // The test performs the following steps: -// 1. Compiles the arma binary. -// 2. Creates a temporary directory for test artifacts. -// 3. Generates a network configuration YAML file. -// 4. Uses the armageddon CLI to generate config files for the network. -// 5. Starts the arma nodes and waits for them to be ready. -// 6. Sends a specified number of transactions to the router using a rate limiter. -// 7. Queries the router's metrics endpoint and asserts that the number of incoming transactions matches the number sent, within a timeout period. -// 8. Queries the router's health check endpoint and asserts that the health status is "healthy" within a timeout period. +// 1. Compile the arma binary. +// 2. Create a temporary directory for the test. +// 3. Create a config YAML file in the temporary directory. +// 4. Generate the config files in the temporary directory using the armageddon generate command. +// 5. Run the arma nodes. +// 6. Send transactions to the routers. +// 7. Verify that the router's log output contains DEBUG level logs after sending transactions. +// 8. Query the router's metrics endpoint and assert the incoming transaction count. +// 9. Query the router's health check endpoint and assert the health status. +// 10. Verify that the router's log output contains DEBUG level logs after sending transactions. +// 11. Query the router's metrics endpoint and assert the incoming transaction count. +// 12. Query the router's health check endpoint and assert the health status. func TestSubmitToRouterGetResponseFromOperationEndpoints(t *testing.T) { // 1. compile arma armaBinaryPath, err := gexec.BuildWithEnvironment("github.com/hyperledger/fabric-x-orderer/cmd/arma", []string{"GOPRIVATE=" + os.Getenv("GOPRIVATE")}) - defer gexec.CleanupBuildArtifacts() + t.Cleanup(func() { + gexec.CleanupBuildArtifacts() + }) require.NoError(t, err) require.NotNil(t, armaBinaryPath) @@ -57,12 +64,16 @@ func TestSubmitToRouterGetResponseFromOperationEndpoints(t *testing.T) { // 2. Create a temporary directory for the test. dir, err := os.MkdirTemp("", t.Name()) require.NoError(t, err) - defer os.RemoveAll(dir) + t.Cleanup(func() { + os.RemoveAll(dir) + }) // 3. Create a config YAML file in the temporary directory. configPath := filepath.Join(dir, "config.yaml") netInfo := testutil.CreateNetwork(t, configPath, numOfParties, 1, "none", "none") - defer netInfo.CleanUp() + t.Cleanup(func() { + netInfo.CleanUp() + }) numOfArmaNodes := len(netInfo) // 4. Generate the config files in the temporary directory using the armageddon generate command. @@ -72,7 +83,9 @@ func TestSubmitToRouterGetResponseFromOperationEndpoints(t *testing.T) { // NOTE: if one of the nodes is not started within 10 seconds, there is no point in continuing the test, so fail it readyChan := make(chan string, numOfArmaNodes) armaNetwork := testutil.RunArmaNodes(t, dir, armaBinaryPath, readyChan, netInfo) - defer armaNetwork.Stop() + t.Cleanup(func() { + armaNetwork.Stop() + }) testutil.WaitReady(t, readyChan, numOfArmaNodes, 10) @@ -80,7 +93,43 @@ func TestSubmitToRouterGetResponseFromOperationEndpoints(t *testing.T) { require.NoError(t, err) require.NotNil(t, uc) - // 6. Send transactions to the routers. + routerToTest := armaNetwork.GetRouter(t, 1) + + // 6. verify that the router's log output does not contain DEBUG level logs + debugRe := regexp.MustCompile("DEBU") + matches := debugRe.FindStringSubmatch(string(routerToTest.RunInfo.Session.Err.Contents())) + require.Len(t, matches, 0, "expected to not find DEBUG logs in router output") + + // 7. Query the router's log specification endpoint. + logSpecUrl := testutil.CaptureArmaNodeLogSpecServiceURL(t, routerToTest) + logSpecRe := regexp.MustCompile(`^\{\s*"spec"\s*:\s*"([^"]*)"\s*\}`) + + require.Eventually(t, func() bool { + logSpec := testutil.FetchLogSpecValue(t, logSpecRe, logSpecUrl) + if logSpec == nil { + return false + } + if logSpec.Spec == "info" { + return true + } + return false + }, 30*time.Second, 100*time.Millisecond) + + // 8. Update the router's log specification to "debug" and assert the change is reflected. + testutil.UpdateLogSpecValue(t, logSpecUrl, &httpadmin.LogSpec{Spec: "debug"}) + + require.Eventually(t, func() bool { + logSpec := testutil.FetchLogSpecValue(t, logSpecRe, logSpecUrl) + if logSpec == nil { + return false + } + if logSpec.Spec == "debug" { + return true + } + return false + }, 30*time.Second, 100*time.Millisecond) + + // 9. Send transactions to the routers. totalTxNumber := 100 // rate limiter parameters fillInterval := 10 * time.Millisecond @@ -89,44 +138,40 @@ func TestSubmitToRouterGetResponseFromOperationEndpoints(t *testing.T) { capacity := rate / fillFrequency rl, err := armageddon.NewRateLimiter(rate, fillInterval, capacity) - if err != nil { - fmt.Fprintf(os.Stderr, "failed to start a rate limiter") - os.Exit(3) - } + require.NoError(t, err) broadcastClient := client.NewBroadcastTxClient(uc, 10*time.Second) defer broadcastClient.Stop() for i := range totalTxNumber { status := rl.GetToken() - if !status { - fmt.Fprintf(os.Stderr, "failed to send tx %d", i+1) - os.Exit(3) - } + require.Truef(t, status, "failed to send tx %d", i+1) txContent := tx.PrepareTxWithTimestamp(i, 64, []byte("sessionNumber")) env := tx.CreateStructuredEnvelope(txContent) err = broadcastClient.SendTx(env) require.NoError(t, err) } - // 7. Query the router's metrics endpoint and assert the incoming transaction count. - routerToMonitor := armaNetwork.GetRouter(t, 1) - url := testutil.CaptureArmaNodePrometheusServiceURL(t, routerToMonitor) - - pattern := fmt.Sprintf(`router_requests_completed\{party_id="%d"\} \d+`, types.PartyID(1)) - re := regexp.MustCompile(pattern) + // 10. Verify that the router's log output contains DEBUG level logs after sending transactions. require.Eventually(t, func() bool { - return testutil.FetchPrometheusMetricValue(t, re, url) == totalTxNumber + matches := debugRe.FindStringSubmatch(string(routerToTest.RunInfo.Session.Err.Contents())) + return len(matches) > 0 }, 30*time.Second, 100*time.Millisecond) - // 8. Query the router's health check endpoint and assert the health status. - url = testutil.CaptureArmaNodeHealthCheckServiceURL(t, routerToMonitor) + // 11. Query the router's metrics endpoint and assert the incoming transaction count. + prometheusUrl := testutil.CaptureArmaNodePrometheusServiceURL(t, routerToTest) + prometheusRe := regexp.MustCompile(fmt.Sprintf(`router_requests_completed\{party_id="%d"\} \d+`, types.PartyID(1))) + + require.Eventually(t, func() bool { + return testutil.FetchPrometheusMetricValue(t, prometheusRe, prometheusUrl) == totalTxNumber + }, 30*time.Second, 100*time.Millisecond) - pattern = `^\{\s*"status"\s*:\s*"([^"]+)"(?:\s*,\s*"time"\s*:\s*"[^"]*")?\s*\}$` - re = regexp.MustCompile(pattern) + // 12. Query the router's health check endpoint and assert the health status. + healthCheckUrl := testutil.CaptureArmaNodeHealthCheckServiceURL(t, routerToTest) + healthCheckRe := regexp.MustCompile(`^\{\s*"status"\s*:\s*"([^"]+)"(?:\s*,\s*"time"\s*:\s*"[^"]*")?\s*\}$`) require.Eventually(t, func() bool { - return testutil.GetHealthCheckStatus(t, re, url) + return testutil.GetHealthCheckStatus(t, healthCheckRe, healthCheckUrl) }, 30*time.Second, 100*time.Millisecond) } diff --git a/test/faulttolerance/assembler_test.go b/test/faulttolerance/assembler_test.go index 7983b2337..10255d5ca 100644 --- a/test/faulttolerance/assembler_test.go +++ b/test/faulttolerance/assembler_test.go @@ -21,9 +21,11 @@ import ( "testing" "time" + "github.com/hyperledger/fabric-lib-go/common/flogging/httpadmin" "github.com/hyperledger/fabric-protos-go-apiv2/common" "github.com/hyperledger/fabric-x-orderer/common/tools/armageddon" "github.com/hyperledger/fabric-x-orderer/common/types" + test_utils "github.com/hyperledger/fabric-x-orderer/test/utils" "github.com/hyperledger/fabric-x-orderer/testutil" "github.com/hyperledger/fabric-x-orderer/testutil/client" "github.com/hyperledger/fabric-x-orderer/testutil/signutil" @@ -155,15 +157,23 @@ func TestSubmitStopThenRestartAssembler(t *testing.T) { // 6. Stops and restarts the monitored assembler node // 7. Verifies that the metrics remain accurate after the node restart // 8. Checks the health check endpoint to ensure the assembler node is healthy +// 9. Verifies that the assembler's log output does not contain DEBUG level logs +// 10. Checks the log specification endpoint to ensure the log spec is "info" +// 11. Updates the log specification to "debug" and verifies the change is reflected +// 12. Pull transactions to generate DEBUG level logs and verifies that the assembler's log output contains DEBUG logs func TestStartAssemblerGetResponseFromOperationEndpoints(t *testing.T) { dir, err := os.MkdirTemp("", t.Name()) require.NoError(t, err) - defer os.RemoveAll(dir) + t.Cleanup(func() { + os.RemoveAll(dir) + }) // 1. configPath := filepath.Join(dir, "config.yaml") netInfo := testutil.CreateNetwork(t, configPath, 1, 1, "TLS", "TLS") - defer netInfo.CleanUp() + t.Cleanup(func() { + netInfo.CleanUp() + }) // 2. armageddonCLI := armageddon.NewCLI() @@ -181,7 +191,9 @@ func TestStartAssemblerGetResponseFromOperationEndpoints(t *testing.T) { readyChan := make(chan string, nodesNumber) armaNetwork := testutil.RunArmaNodes(t, dir, armaBinaryPath, readyChan, netInfo) - defer armaNetwork.Stop() + t.Cleanup(func() { + armaNetwork.Stop() + }) testutil.WaitReady(t, readyChan, nodesNumber, 10) @@ -194,10 +206,7 @@ func TestStartAssemblerGetResponseFromOperationEndpoints(t *testing.T) { capacity := rate / fillFrequency rl, err := armageddon.NewRateLimiter(rate, fillInterval, capacity) - if err != nil { - fmt.Fprintf(os.Stderr, "failed to start a rate limiter") - os.Exit(3) - } + require.NoError(t, err) uc, err := testutil.GetUserConfig(dir, 1) require.NoError(t, err) @@ -207,10 +216,7 @@ func TestStartAssemblerGetResponseFromOperationEndpoints(t *testing.T) { for i := range totalTxNumber { status := rl.GetToken() - if !status { - fmt.Fprintf(os.Stderr, "failed to send tx %d", i+1) - os.Exit(3) - } + require.Truef(t, status, "failed to send tx %d", i+1) txContent := tx.PrepareTxWithTimestamp(i, 64, []byte("sessionNumber")) env := tx.CreateStructuredEnvelope(txContent) err = broadcastClient.SendTx(env) @@ -218,8 +224,8 @@ func TestStartAssemblerGetResponseFromOperationEndpoints(t *testing.T) { } // 5. - assemblerToMonitor := armaNetwork.GetAssembler(t, types.PartyID(1)) - url := testutil.CaptureArmaNodePrometheusServiceURL(t, assemblerToMonitor) + assemblerToTest := armaNetwork.GetAssembler(t, types.PartyID(1)) + prometheusURL := testutil.CaptureArmaNodePrometheusServiceURL(t, assemblerToTest) txsCountPattern := fmt.Sprintf(`assembler_ledger_transaction_count_total\{party_id="%d"\} \d+`, types.PartyID(1)) txsCountRe := regexp.MustCompile(txsCountPattern) @@ -228,32 +234,81 @@ func TestStartAssemblerGetResponseFromOperationEndpoints(t *testing.T) { blocksCountRe := regexp.MustCompile(blocksCountPattern) require.Eventually(t, func() bool { - return testutil.FetchPrometheusMetricValue(t, txsCountRe, url) == totalTxNumber+1 + return testutil.FetchPrometheusMetricValue(t, txsCountRe, prometheusURL) == totalTxNumber+1 }, 30*time.Second, 100*time.Millisecond) - require.GreaterOrEqual(t, testutil.FetchPrometheusMetricValue(t, blocksCountRe, url), 2) + require.GreaterOrEqual(t, testutil.FetchPrometheusMetricValue(t, blocksCountRe, prometheusURL), 2) // 6. - assemblerToMonitor.StopArmaNode() - assemblerToMonitor.RestartArmaNode(t, readyChan) + assemblerToTest.StopArmaNode() + assemblerToTest.RestartArmaNode(t, readyChan) // 7. testutil.WaitReady(t, readyChan, 1, 10) - url = testutil.CaptureArmaNodePrometheusServiceURL(t, assemblerToMonitor) + prometheusURL = testutil.CaptureArmaNodePrometheusServiceURL(t, assemblerToTest) require.Eventually(t, func() bool { - return testutil.FetchPrometheusMetricValue(t, txsCountRe, url) == totalTxNumber+1 + return testutil.FetchPrometheusMetricValue(t, txsCountRe, prometheusURL) == totalTxNumber+1 }, 30*time.Second, 100*time.Millisecond) - require.GreaterOrEqual(t, testutil.FetchPrometheusMetricValue(t, blocksCountRe, url), 2) + require.GreaterOrEqual(t, testutil.FetchPrometheusMetricValue(t, blocksCountRe, prometheusURL), 2) // 8. - url = testutil.CaptureArmaNodeHealthCheckServiceURL(t, assemblerToMonitor) + healthCheckURL := testutil.CaptureArmaNodeHealthCheckServiceURL(t, assemblerToTest) + healthCheckRe := regexp.MustCompile(`^\{\s*"status"\s*:\s*"([^"]+)"(?:\s*,\s*"time"\s*:\s*"[^"]*")?\s*\}$`) + + require.Eventually(t, func() bool { + return testutil.GetHealthCheckStatus(t, healthCheckRe, healthCheckURL) + }, 30*time.Second, 100*time.Millisecond) + + // 9. + debugRe := regexp.MustCompile("DEBU") + matches := debugRe.FindStringSubmatch(string(assemblerToTest.RunInfo.Session.Err.Contents())) + require.Len(t, matches, 0, "expected to not find DEBUG logs in assembler output") + + // 10. + logSpecURL := testutil.CaptureArmaNodeLogSpecServiceURL(t, assemblerToTest) + logSpecRe := regexp.MustCompile(`^\{\s*"spec"\s*:\s*"([^"]*)"\s*\}`) + + require.Eventually(t, func() bool { + logSpec := testutil.FetchLogSpecValue(t, logSpecRe, logSpecURL) + if logSpec == nil { + return false + } + if logSpec.Spec == "info" { + return true + } + return false + }, 30*time.Second, 100*time.Millisecond) + + // 11. + testutil.UpdateLogSpecValue(t, logSpecURL, &httpadmin.LogSpec{Spec: "debug"}) + + require.Eventually(t, func() bool { + logSpec := testutil.FetchLogSpecValue(t, logSpecRe, logSpecURL) + if logSpec == nil { + return false + } + if logSpec.Spec == "debug" { + return true + } + return false + }, 30*time.Second, 100*time.Millisecond) - pattern := `^\{\s*"status"\s*:\s*"([^"]+)"(?:\s*,\s*"time"\s*:\s*"[^"]*")?\s*\}$` - re := regexp.MustCompile(pattern) + // 12. + test_utils.PullFromAssemblers(t, &test_utils.BlockPullerOptions{ + Parties: []types.PartyID{1}, + UserConfig: uc, + StartBlock: 0, + EndBlock: math.MaxUint64, + Transactions: totalTxNumber, + Timeout: 60, + ErrString: "cancelled pull from assembler: %d", + Signer: signutil.CreateTestSigner(t, "org1", dir), + }) require.Eventually(t, func() bool { - return testutil.GetHealthCheckStatus(t, re, url) + matches := debugRe.FindStringSubmatch(string(assemblerToTest.RunInfo.Session.Err.Contents())) + return len(matches) > 0 }, 30*time.Second, 100*time.Millisecond) } diff --git a/test/faulttolerance/router_test.go b/test/faulttolerance/router_test.go index 8aa8a418d..4253f300e 100644 --- a/test/faulttolerance/router_test.go +++ b/test/faulttolerance/router_test.go @@ -253,10 +253,7 @@ func TestRouterRestartRecover(t *testing.T) { for i := range totalTxNumber { status := rl.GetToken() - if !status { - fmt.Fprintf(os.Stderr, "failed to send tx %d", i+1) - os.Exit(3) - } + require.Truef(t, status, "failed to send tx %d", i+1) txContent := tx.PrepareTxWithTimestamp(totalTxSent+i, 64, []byte("sessionNumber")) env := tx.CreateStructuredEnvelope(txContent) err = broadcastClient.SendTx(env) diff --git a/testutil/network_utils.go b/testutil/network_utils.go index 0ebb112e1..ccf366cbb 100644 --- a/testutil/network_utils.go +++ b/testutil/network_utils.go @@ -7,7 +7,9 @@ SPDX-License-Identifier: Apache-2.0 package testutil import ( + "bytes" "context" + "encoding/json" "io" "net" "net/http" @@ -18,7 +20,9 @@ import ( "testing" "time" + "github.com/hyperledger/fabric-lib-go/common/flogging/httpadmin" "github.com/hyperledger/fabric-lib-go/healthz" + "github.com/stretchr/testify/require" ) @@ -54,11 +58,16 @@ func GetAvailablePort(t testing.TB) (port string, ll net.Listener) { // FetchPrometheusMetricValue fetches the value of a Prometheus metric from the specified URL using the provided regular expression. // It returns the metric value as an integer. If the metric is not found or cannot be converted to an integer, it returns -1. func FetchPrometheusMetricValue(t *testing.T, re *regexp.Regexp, url string) int { - resp, err := http.Get(url) + client := &http.Client{Timeout: 5 * time.Second} + resp, err := client.Get(url) require.NoError(t, err) defer resp.Body.Close() + if resp.StatusCode != http.StatusOK { + return -1 + } + body, err := io.ReadAll(resp.Body) require.NoError(t, err) @@ -81,8 +90,12 @@ func FetchPrometheusMetricValue(t *testing.T, re *regexp.Regexp, url string) int // CaptureArmaNodePrometheusServiceURL retrieves the Prometheus metrics endpoint URL from the given ArmaNodeInfo's session output. // It waits until the URL is found or times out, and returns the metrics endpoint as a string. func CaptureArmaNodePrometheusServiceURL(t *testing.T, armaNodeInfo *ArmaNodeInfo) string { + return captureArmaNodeServiceURL(t, armaNodeInfo, `Prometheus serving on URL:\s+(https?://[^/\s]+/metrics)`) +} + +func captureArmaNodeServiceURL(t *testing.T, armaNodeInfo *ArmaNodeInfo, regex string) string { var url string - re := regexp.MustCompile(`Prometheus serving on URL:\s+(https?://[^/\s]+/metrics)`) + re := regexp.MustCompile(regex) require.Eventually(t, func() bool { output := string(armaNodeInfo.RunInfo.Session.Err.Contents()) matches := re.FindStringSubmatch(output) @@ -96,6 +109,39 @@ func CaptureArmaNodePrometheusServiceURL(t *testing.T, armaNodeInfo *ArmaNodeInf return url } +// CaptureArmaNodeLogSpecServiceURL retrieves the log specification endpoint URL from the given ArmaNodeInfo's session output. +// It waits until the URL is found or times out, and returns the log specification endpoint as a string. +func CaptureArmaNodeLogSpecServiceURL(t *testing.T, armaNodeInfo *ArmaNodeInfo) string { + return captureArmaNodeServiceURL(t, armaNodeInfo, `Logging spec service serving on URL:\s+(https?://[^/\s]+/logspec)`) +} + +// FetchLogSpecValue fetches the log specification value from the specified URL using the provided regular expression. +// It returns a pointer to a LogSpec struct if the value is successfully retrieved and parsed, or nil if an error occurs. +func FetchLogSpecValue(t *testing.T, re *regexp.Regexp, url string) *httpadmin.LogSpec { + client := &http.Client{Timeout: 5 * time.Second} + resp, err := client.Get(url) + require.NoError(t, err) + + defer resp.Body.Close() + + if resp.StatusCode != http.StatusOK { + return nil + } + + body, err := io.ReadAll(resp.Body) + require.NoError(t, err) + + t.Log(string(body)) + + // Find all matches + matches := re.FindStringSubmatch(string(body)) + if len(matches) > 1 { + return &httpadmin.LogSpec{Spec: matches[1]} + } + + return nil +} + // GetHealthCheckStatus retrieves the health status from the given health check endpoint URL using the provided regular expression. // It returns true if the status is "OK", false if the status is "Unavailable", and fails the test for any unexpected response. func GetHealthCheckStatus(t *testing.T, re *regexp.Regexp, url string) bool { @@ -125,17 +171,29 @@ func GetHealthCheckStatus(t *testing.T, re *regexp.Regexp, url string) bool { // CaptureArmaNodeHealthCheckServiceURL retrieves the health check endpoint URL from the given ArmaNodeInfo's session output. // It waits until the URL is found or times out, and returns the health check endpoint as a string. func CaptureArmaNodeHealthCheckServiceURL(t *testing.T, armaNodeInfo *ArmaNodeInfo) string { - var url string - re := regexp.MustCompile(`Health check serving on URL:\s+(https?://[^/\s]+/healthz)`) - require.Eventually(t, func() bool { - output := string(armaNodeInfo.RunInfo.Session.Err.Contents()) - matches := re.FindStringSubmatch(output) - if len(matches) > 1 { - url = matches[1] - return true - } - return false - }, 60*time.Second, 10*time.Millisecond) + return captureArmaNodeServiceURL(t, armaNodeInfo, `Health check serving on URL:\s+(https?://[^/\s]+/healthz)`) +} - return url +// UpdateLogSpecValue updates the log specification value at the specified URL using an HTTP PUT request with the provided LogSpec. +// It asserts that the request is successful and returns without error. +func UpdateLogSpecValue(t *testing.T, url string, logSpec *httpadmin.LogSpec) { + resp, err := putJSON(url, logSpec) + require.NoError(t, err) + defer resp.Body.Close() + + require.Equal(t, http.StatusNoContent, resp.StatusCode) +} + +func putJSON(url string, v any) (*http.Response, error) { + b, err := json.Marshal(v) + if err != nil { + return nil, err + } + req, err := http.NewRequest(http.MethodPut, url, bytes.NewReader(b)) + if err != nil { + return nil, err + } + req.Header.Set("Content-Type", "application/json") + client := &http.Client{Timeout: 5 * time.Second} + return client.Do(req) } diff --git a/vendor/github.com/hyperledger/fabric-lib-go/common/flogging/httpadmin/spec.go b/vendor/github.com/hyperledger/fabric-lib-go/common/flogging/httpadmin/spec.go new file mode 100644 index 000000000..c887492e1 --- /dev/null +++ b/vendor/github.com/hyperledger/fabric-lib-go/common/flogging/httpadmin/spec.go @@ -0,0 +1,83 @@ +/* +Copyright IBM Corp. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package httpadmin + +import ( + "encoding/json" + "fmt" + "net/http" + + "github.com/hyperledger/fabric-lib-go/common/flogging" +) + +//go:generate counterfeiter -o fakes/logging.go -fake-name Logging . Logging + +type Logging interface { + ActivateSpec(spec string) error + Spec() string +} + +// swagger:model spec +type LogSpec struct { + Spec string `json:"spec,omitempty"` +} + +type ErrorResponse struct { + Error string `json:"error"` +} + +func NewSpecHandler() *SpecHandler { + return &SpecHandler{ + Logging: flogging.Global, + Logger: flogging.MustGetLogger("flogging.httpadmin"), + } +} + +type SpecHandler struct { + Logging Logging + Logger *flogging.FabricLogger +} + +func (h *SpecHandler) ServeHTTP(resp http.ResponseWriter, req *http.Request) { + switch req.Method { + case http.MethodPut: + var logSpec LogSpec + decoder := json.NewDecoder(req.Body) + if err := decoder.Decode(&logSpec); err != nil { + h.sendResponse(resp, http.StatusBadRequest, err) + return + } + req.Body.Close() + + if err := h.Logging.ActivateSpec(logSpec.Spec); err != nil { + h.sendResponse(resp, http.StatusBadRequest, err) + return + } + resp.WriteHeader(http.StatusNoContent) + + case http.MethodGet: + h.sendResponse(resp, http.StatusOK, &LogSpec{Spec: h.Logging.Spec()}) + + default: + err := fmt.Errorf("invalid request method: %s", req.Method) + h.sendResponse(resp, http.StatusBadRequest, err) + } +} + +func (h *SpecHandler) sendResponse(resp http.ResponseWriter, code int, payload interface{}) { + encoder := json.NewEncoder(resp) + if err, ok := payload.(error); ok { + payload = &ErrorResponse{Error: err.Error()} + } + + resp.Header().Set("Content-Type", "application/json") + resp.WriteHeader(code) + + if err := encoder.Encode(payload); err != nil { + h.Logger.Errorw("failed to encode payload", "error", err) + } +} diff --git a/vendor/modules.txt b/vendor/modules.txt index 52a09aea4..3b0d0ec8c 100644 --- a/vendor/modules.txt +++ b/vendor/modules.txt @@ -222,6 +222,7 @@ github.com/hyperledger/fabric-lib-go/bccsp/sw github.com/hyperledger/fabric-lib-go/bccsp/utils github.com/hyperledger/fabric-lib-go/common/flogging github.com/hyperledger/fabric-lib-go/common/flogging/fabenc +github.com/hyperledger/fabric-lib-go/common/flogging/httpadmin github.com/hyperledger/fabric-lib-go/common/metrics github.com/hyperledger/fabric-lib-go/common/metrics/disabled github.com/hyperledger/fabric-lib-go/common/metrics/metricsfakes