Merge pull request #549 from BuxOrg/chore-351-pulse-req-logging

chore(BUX-351): improve logging when requesting Pulse

chainstate/client.go

@@ -40,7 +40,7 @@ type (
 		network           Network                    // Current network (mainnet, testnet, stn)
 		queryTimeout      time.Duration              // Timeout for transaction query
 		broadcastClient   broadcast.Client           // Broadcast client
-		pulseClient       *PulseClient               // Pulse client
+		pulseClient       *pulseClientProvider       // Pulse client
 		feeUnit           *utils.FeeUnit             // The lowest fees among all miners
 		feeQuotes         bool                       // If set, feeUnit will be updated with fee quotes from miner's
 	}
@@ -53,12 +53,6 @@ type (
 		apiType   minercraft.APIType      // MinerCraft APIType(ARC/mAPI)
 		minerAPIs []*minercraft.MinerAPIs // List of miners APIs
 	}
-
-	// PulseClient is the internal chainstate pulse client
-	PulseClient struct {
-		url       string
-		authToken string
-	}
 )
 
 // NewClient creates a new client for all on-chain functionality

chainstate/client_options.go

@@ -181,6 +181,6 @@ func WithBroadcastClient(client broadcast.Client) ClientOps {
 // WithConnectionToPulse will set pulse API settings.
 func WithConnectionToPulse(url, authToken string) ClientOps {
 	return func(c *clientOptions) {
-		c.config.pulseClient = &PulseClient{url, authToken}
+		c.config.pulseClient = newPulseClientProvider(url, authToken)
 	}
 }

chainstate/merkle_root.go

@@ -3,19 +3,18 @@ package chainstate
 import (
 	"context"
 	"errors"
-	"fmt"
 )
 
 // VerifyMerkleRoots will try to verify merkle roots with all available providers
+// When no error is returned, it means that the pulse client responded with state: Confirmed or UnableToVerify
 func (c *Client) VerifyMerkleRoots(ctx context.Context, merkleRoots []MerkleRootConfirmationRequestItem) error {
-	if c.options.config.pulseClient == nil {
+	pc := c.options.config.pulseClient
+	if pc == nil {
 		c.options.logger.Warn().Msg("VerifyMerkleRoots is called even though no pulse client is configured; this likely indicates that the paymail capabilities have been cached.")
 		return errors.New("no pulse client found")
 	}
-	pulseProvider := createPulseProvider(c)
-	merkleRootsRes, err := pulseProvider.verifyMerkleRoots(ctx, c, merkleRoots)
+	merkleRootsRes, err := pc.verifyMerkleRoots(ctx, c.options.logger, merkleRoots)
 	if err != nil {
-		debugLog(c, "", fmt.Sprintf("verify merkle root error: %s from Pulse", err))
 		return err
 	}
 
@@ -30,10 +29,3 @@ func (c *Client) VerifyMerkleRoots(ctx context.Context, merkleRoots []MerkleRoot
 
 	return nil
 }
-
-func createPulseProvider(c *Client) pulseClientProvider {
-	return pulseClientProvider{
-		url:       c.options.config.pulseClient.url,
-		authToken: c.options.config.pulseClient.authToken,
-	}
-}

chainstate/merkle_root_provider.go

@@ -5,8 +5,9 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
-	"io"
 	"net/http"
+
+	"github.com/rs/zerolog"
 )
 
 // MerkleRootConfirmationState represents the state of each Merkle Root verification
@@ -46,47 +47,63 @@ type MerkleRootsConfirmationsResponse struct {
 }
 
 type pulseClientProvider struct {
-	url       string
-	authToken string
+	url        string
+	authToken  string
+	httpClient *http.Client
+}
+
+func newPulseClientProvider(url, authToken string) *pulseClientProvider {
+	return &pulseClientProvider{url: url, authToken: authToken, httpClient: &http.Client{}}
 }
 
-// verifyMerkleProof using Pulse
-func (p pulseClientProvider) verifyMerkleRoots(
+func (p *pulseClientProvider) verifyMerkleRoots(
 	ctx context.Context,
-	c *Client, merkleRoots []MerkleRootConfirmationRequestItem,
+	logger *zerolog.Logger,
+	merkleRoots []MerkleRootConfirmationRequestItem,
 ) (*MerkleRootsConfirmationsResponse, error) {
 	jsonData, err := json.Marshal(merkleRoots)
 	if err != nil {
-		return nil, err
+		return nil, _fmtAndLogError(err, logger, "Error occurred while marshaling merkle roots.")
 	}
 
-	client := &http.Client{}
 	req, err := http.NewRequestWithContext(ctx, "POST", p.url, bytes.NewBuffer(jsonData))
 	if err != nil {
-		return nil, err
+		return nil, _fmtAndLogError(err, logger, "Error occurred while creating request for the pulse client.")
 	}
 
 	if p.authToken != "" {
 		req.Header.Set("Authorization", "Bearer "+p.authToken)
 	}
-	res, err := client.Do(req)
+	res, err := p.httpClient.Do(req)
+	if res != nil {
+		defer func() {
+			_ = res.Body.Close()
+		}()
+	}
 	if err != nil {
-		c.options.logger.Error().Msgf("Error during creating connection to pulse client: %s", err.Error())
-		return nil, err
+		return nil, _fmtAndLogError(err, logger, "Error occurred while sending request to the Pulse service.")
 	}
-	defer res.Body.Close() //nolint: all // Close the body
 
-	// Parse response body.
-	var merkleRootsRes MerkleRootsConfirmationsResponse
-	bodyBytes, err := io.ReadAll(res.Body)
-	if err != nil {
-		return nil, fmt.Errorf("error during reading response body: %s", err.Error())
+	if res.StatusCode != 200 {
+		return nil, _fmtAndLogError(_statusError(res.StatusCode), logger, "Received unexpected status code from Pulse service.")
 	}
 
-	err = json.Unmarshal(bodyBytes, &merkleRootsRes)
+	// Parse response body.
+	var merkleRootsRes MerkleRootsConfirmationsResponse
+	err = json.NewDecoder(res.Body).Decode(&merkleRootsRes)
 	if err != nil {
-		return nil, fmt.Errorf("error during unmarshalling response body: %s", err.Error())
+		return nil, _fmtAndLogError(err, logger, "Error occurred while parsing response from the Pulse service.")
 	}
 
 	return &merkleRootsRes, nil
 }
+
+// _fmtAndLogError returns brief error for http response message and logs detailed information with original error
+func _fmtAndLogError(err error, logger *zerolog.Logger, message string) error {
+	logger.Error().Err(err).Msg("[verifyMerkleRoots] " + message)
+	return fmt.Errorf("cannot verify transaction - %s", message)
+}
+
+func _statusError(statusCode int) error {
+	return fmt.Errorf("pulse client returned status code %d - check Pulse configuration and service status", statusCode)
+}

chainstate/merkle_root_test.go

@@ -0,0 +1,127 @@
+package chainstate
+
+import (
+	"bytes"
+	"context"
+	"testing"
+
+	"github.com/jarcoal/httpmock"
+	"github.com/rs/zerolog"
+	"github.com/stretchr/testify/assert"
+)
+
+func initMockClient(ops ...ClientOps) (*Client, *buffLogger) {
+	bLogger := newBuffLogger()
+	ops = append(ops, WithLogger(bLogger.logger))
+	c, _ := NewClient(
+		context.Background(),
+		ops...,
+	)
+	return c.(*Client), bLogger
+}
+
+func TestVerifyMerkleRoots(t *testing.T) {
+	httpmock.Activate()
+	defer httpmock.DeactivateAndReset()
+
+	mockURL := "http://pulse.test/api/v1/chain/merkleroot/verify"
+
+	t.Run("no pulse client", func(t *testing.T) {
+		c, _ := initMockClient()
+
+		err := c.VerifyMerkleRoots(context.Background(), []MerkleRootConfirmationRequestItem{})
+
+		assert.Error(t, err)
+	})
+
+	t.Run("pulse is not online", func(t *testing.T) {
+		httpmock.Reset()
+		httpmock.RegisterResponder("POST", mockURL,
+			httpmock.NewStringResponder(500, `{"error":"Internal Server Error"}`),
+		)
+		c, bLogger := initMockClient(WithConnectionToPulse(mockURL, ""))
+
+		err := c.VerifyMerkleRoots(context.Background(), []MerkleRootConfirmationRequestItem{})
+
+		assert.Error(t, err)
+		assert.Equal(t, 1, httpmock.GetTotalCallCount())
+		assert.True(t, bLogger.contains("pulse client returned status code 500"))
+	})
+
+	t.Run("pulse wrong auth", func(t *testing.T) {
+		httpmock.Reset()
+		httpmock.RegisterResponder("POST", mockURL,
+			httpmock.NewStringResponder(401, `Unauthorized`),
+		)
+		c, bLogger := initMockClient(WithConnectionToPulse(mockURL, "some-token"))
+
+		err := c.VerifyMerkleRoots(context.Background(), []MerkleRootConfirmationRequestItem{})
+
+		assert.Error(t, err)
+		assert.Equal(t, 1, httpmock.GetTotalCallCount())
+		assert.True(t, bLogger.contains("401"))
+	})
+
+	t.Run("pulse invalid state", func(t *testing.T) {
+		httpmock.Reset()
+		httpmock.RegisterResponder("POST", mockURL,
+			httpmock.NewJsonResponderOrPanic(200, MerkleRootsConfirmationsResponse{
+				ConfirmationState: Invalid,
+				Confirmations:     []MerkleRootConfirmation{},
+			}),
+		)
+		c, bLogger := initMockClient(WithConnectionToPulse(mockURL, "some-token"))
+
+		err := c.VerifyMerkleRoots(context.Background(), []MerkleRootConfirmationRequestItem{})
+
+		assert.Error(t, err)
+		assert.Equal(t, 1, httpmock.GetTotalCallCount())
+		assert.True(t, bLogger.contains("Not all merkle roots confirmed"))
+	})
+
+	t.Run("pulse confirmedState", func(t *testing.T) {
+		httpmock.Reset()
+		httpmock.RegisterResponder("POST", mockURL,
+			httpmock.NewJsonResponderOrPanic(200, MerkleRootsConfirmationsResponse{
+				ConfirmationState: Confirmed,
+				Confirmations: []MerkleRootConfirmation{
+					{
+						Hash:         "some-hash",
+						BlockHeight:  1,
+						MerkleRoot:   "some-merkle-root",
+						Confirmation: Confirmed,
+					},
+				},
+			}),
+		)
+		c, bLogger := initMockClient(WithConnectionToPulse(mockURL, "some-token"))
+
+		err := c.VerifyMerkleRoots(context.Background(), []MerkleRootConfirmationRequestItem{
+			{
+				MerkleRoot:  "some-merkle-root",
+				BlockHeight: 1,
+			},
+		})
+
+		assert.NoError(t, err)
+		assert.Equal(t, 1, httpmock.GetTotalCallCount())
+		assert.False(t, bLogger.contains("ERR"))
+		assert.False(t, bLogger.contains("WARN"))
+	})
+}
+
+// buffLogger allows to check if a certain string was logged
+type buffLogger struct {
+	logger *zerolog.Logger
+	buf    *bytes.Buffer
+}
+
+func newBuffLogger() *buffLogger {
+	var buf bytes.Buffer
+	logger := zerolog.New(&buf).Level(zerolog.DebugLevel).With().Logger()
+	return &buffLogger{logger: &logger, buf: &buf}
+}
+
+func (l *buffLogger) contains(expected string) bool {
+	return bytes.Contains(l.buf.Bytes(), []byte(expected))
+}