Operations endpoints: logspec handler

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)
+}

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

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 {

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()
 

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)
 }
 

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,70 +287,145 @@ 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())
 	rate := 500
 
 	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)
 }