4783 poet client logging (#4988)

## Motivation
Part of  #4751 
Closes #4783

## Changes
- use local logger in poet clients
- provide the logger to `retryablehttp` to gain visibility on performed requests, retries, responses etc.
- cleanup poet test harness

## Test Plan
Existing tests pass

CHANGELOG.md

@@ -107,3 +107,4 @@ Doesn't affect direct peers. In order to disable:
 * [#4882](https://github.com/spacemeshos/go-spacemesh/pull/4882) Increase cache size and parametrize datastore.
 * [#4887](https://github.com/spacemeshos/go-spacemesh/pull/4887) Fixed crashes on API call.
 * [#4871](https://github.com/spacemeshos/go-spacemesh/pull/4871) Add jitter to spread out requests to get poet proof and submit challenge
+* [#4988](https://github.com/spacemeshos/go-spacemesh/pull/4988) Improve logging around communication with PoET services

activation/nipost.go

@@ -135,7 +135,7 @@ func NewNIPostBuilder(
 ) (*NIPostBuilder, error) {
 	poetClients := make(map[string]PoetProvingServiceClient, len(poetServers))
 	for _, address := range poetServers {
-		client, err := NewHTTPPoetClient(address, poetCfg)
+		client, err := NewHTTPPoetClient(address, poetCfg, WithLogger(lg.Zap().Named("poet")))
 		if err != nil {
 			return nil, fmt.Errorf("cannot create poet client: %w", err)
 		}

activation/nipost_test.go

@@ -8,12 +8,14 @@ import (
 	"time"
 
 	"github.com/spacemeshos/go-scale/tester"
+	"github.com/spacemeshos/poet/logging"
 	"github.com/spacemeshos/post/proving"
 	"github.com/spacemeshos/post/verifying"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 	"go.uber.org/mock/gomock"
 	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap/zaptest"
 	"golang.org/x/sync/errgroup"
 
 	"github.com/spacemeshos/go-spacemesh/common/types"
@@ -167,24 +169,24 @@ func TestNIPostBuilderWithClients(t *testing.T) {
 	require.NoError(t, err)
 }
 
-func spawnPoet(tb testing.TB, clientCfg PoetConfig, opts ...HTTPPoetOpt) *HTTPPoetClient {
+func spawnPoet(tb testing.TB, opts ...HTTPPoetOpt) *HTTPPoetTestHarness {
 	tb.Helper()
-	poetProver, err := NewHTTPPoetTestHarness(context.Background(), tb.TempDir(), clientCfg, opts...)
+	ctx, cancel := context.WithCancel(logging.NewContext(context.Background(), zaptest.NewLogger(tb)))
+
+	poetProver, err := NewHTTPPoetTestHarness(ctx, tb.TempDir(), opts...)
 	require.NoError(tb, err)
 	require.NotNil(tb, poetProver)
 
 	var eg errgroup.Group
-	ctx, cancel := context.WithCancel(context.Background())
 	tb.Cleanup(func() {
 		cancel()
-		assert.NoError(tb, eg.Wait())
+		eg.Wait()
 	})
 	eg.Go(func() error {
 		return poetProver.Service.Start(ctx)
 	})
-	_, err = poetProver.HTTPPoetClient.PoetServiceID(context.Background())
-	require.NoError(tb, err)
-	return poetProver.HTTPPoetClient
+
+	return poetProver
 }
 
 func buildNIPost(tb testing.TB, postProvider *testPostManager, nipostChallenge types.NIPostChallenge, poetDb poetDbAPI, validator nipostValidator) *types.NIPost {
@@ -201,22 +203,21 @@ func buildNIPost(tb testing.TB, postProvider *testPostManager, nipostChallenge t
 		MaxRequestRetries: 10,
 	}
 
-	poetProver := spawnPoet(tb, poetCfg, WithGenesis(time.Now()), WithEpochDuration(epoch), WithPhaseShift(poetCfg.PhaseShift), WithCycleGap(poetCfg.CycleGap))
+	poetProver := spawnPoet(tb, WithGenesis(time.Now()), WithEpochDuration(epoch), WithPhaseShift(poetCfg.PhaseShift), WithCycleGap(poetCfg.CycleGap))
 
 	signer, err := signing.NewEdSigner()
 	require.NoError(tb, err)
 	nb, err := NewNIPostBuilder(
 		postProvider.id,
 		postProvider,
 		poetDb,
-		[]string{},
+		[]string{poetProver.RestURL().String()},
 		tb.TempDir(),
 		logtest.New(tb),
 		signer,
 		poetCfg,
 		mclock,
 		WithNipostValidator(validator),
-		withPoetClients([]PoetProvingServiceClient{poetProver}),
 	)
 	require.NoError(tb, err)
 	nipost, err := nb.BuildNIPost(context.Background(), &nipostChallenge)
@@ -249,7 +250,7 @@ func TestNewNIPostBuilderNotInitialized(t *testing.T) {
 	}
 
 	genesis := time.Now()
-	poetProver := spawnPoet(t, poetCfg, WithGenesis(genesis), WithEpochDuration(epoch), WithPhaseShift(poetCfg.PhaseShift), WithCycleGap(poetCfg.CycleGap))
+	poetProver := spawnPoet(t, WithGenesis(genesis), WithEpochDuration(epoch), WithPhaseShift(poetCfg.PhaseShift), WithCycleGap(poetCfg.CycleGap))
 
 	ctrl := gomock.NewController(t)
 	poetDb := NewMockpoetDbAPI(ctrl)
@@ -266,14 +267,13 @@ func TestNewNIPostBuilderNotInitialized(t *testing.T) {
 		postProvider.id,
 		postProvider,
 		poetDb,
-		[]string{},
+		[]string{poetProver.RestURL().String()},
 		t.TempDir(),
 		logtest.New(t),
 		postProvider.signer,
 		poetCfg,
 		mclock,
 		WithNipostValidator(nipostValidator),
-		withPoetClients([]PoetProvingServiceClient{poetProver}),
 	)
 	require.NoError(t, err)
 
@@ -593,7 +593,7 @@ func TestNIPostBuilder_Close(t *testing.T) {
 	ctrl := gomock.NewController(t)
 	postProvider := NewMockpostSetupProvider(ctrl)
 	postProvider.EXPECT().Status().Return(&PostSetupStatus{State: PostSetupStateComplete})
-	poetProver := spawnPoet(t, DefaultPoetConfig(), WithGenesis(time.Now()), WithEpochDuration(time.Second))
+	poetProver := spawnPoet(t, WithGenesis(time.Now()), WithEpochDuration(time.Second))
 	poetDb := NewMockpoetDbAPI(ctrl)
 	challenge := types.NIPostChallenge{
 		PublishEpoch: postGenesisEpoch + 2,
@@ -606,13 +606,12 @@ func TestNIPostBuilder_Close(t *testing.T) {
 		types.NodeID{1},
 		postProvider,
 		poetDb,
-		[]string{},
+		[]string{poetProver.RestURL().String()},
 		t.TempDir(),
 		logtest.New(t),
 		sig,
 		PoetConfig{},
 		mclock,
-		withPoetClients([]PoetProvingServiceClient{poetProver}),
 	)
 	r.NoError(err)
 

activation/poet.go

@@ -12,11 +12,11 @@ import (
 	"github.com/hashicorp/go-retryablehttp"
 	rpcapi "github.com/spacemeshos/poet/release/proto/go/rpc/api/v1"
 	"github.com/spacemeshos/poet/shared"
+	"go.uber.org/zap"
 	"google.golang.org/protobuf/encoding/protojson"
 	"google.golang.org/protobuf/proto"
 
 	"github.com/spacemeshos/go-spacemesh/common/types"
-	"github.com/spacemeshos/go-spacemesh/log"
 )
 
 var (
@@ -40,6 +40,7 @@ type HTTPPoetClient struct {
 	baseURL       *url.URL
 	poetServiceID types.PoetServiceID
 	client        *retryablehttp.Client
+	logger        *zap.Logger
 }
 
 func defaultPoetClientFunc(address string, cfg PoetConfig) (PoetProvingServiceClient, error) {
@@ -53,6 +54,28 @@ func checkRetry(ctx context.Context, resp *http.Response, err error) (bool, erro
 	return retryablehttp.DefaultRetryPolicy(ctx, resp, err)
 }
 
+// A wrapper around zap.Logger to make it compatible with
+// retryablehttp.LeveledLogger interface.
+type retryableHttpLogger struct {
+	inner *zap.Logger
+}
+
+func (r retryableHttpLogger) Error(format string, args ...any) {
+	r.inner.Sugar().Errorw(format, args...)
+}
+
+func (r retryableHttpLogger) Info(format string, args ...any) {
+	r.inner.Sugar().Infow(format, args...)
+}
+
+func (r retryableHttpLogger) Warn(format string, args ...any) {
+	r.inner.Sugar().Warnw(format, args...)
+}
+
+func (r retryableHttpLogger) Debug(format string, args ...any) {
+	r.inner.Sugar().Debugw(format, args...)
+}
+
 type PoetClientOpts func(*HTTPPoetClient)
 
 func withCustomHttpClient(client *http.Client) PoetClientOpts {
@@ -61,11 +84,22 @@ func withCustomHttpClient(client *http.Client) PoetClientOpts {
 	}
 }
 
+func WithLogger(logger *zap.Logger) PoetClientOpts {
+	return func(c *HTTPPoetClient) {
+		c.logger = logger
+		c.client.Logger = &retryableHttpLogger{inner: logger}
+		c.client.ResponseLogHook = func(logger retryablehttp.Logger, resp *http.Response) {
+			c.logger.Info(
+				"response received",
+				zap.Stringer("url", resp.Request.URL),
+				zap.Int("status", resp.StatusCode),
+			)
+		}
+	}
+}
+
 // NewHTTPPoetClient returns new instance of HTTPPoetClient connecting to the specified url.
 func NewHTTPPoetClient(baseUrl string, cfg PoetConfig, opts ...PoetClientOpts) (*HTTPPoetClient, error) {
-	// TODO(brozansk): Take a logger and use it instead of global logger
-	log.With().Info("creating poet client", log.String("url", baseUrl), log.Int("max_retries", cfg.MaxRequestRetries), log.Stringer("retry_delay", cfg.RequestRetryDelay))
-
 	client := &retryablehttp.Client{
 		RetryMax:     cfg.MaxRequestRetries,
 		RetryWaitMin: cfg.RequestRetryDelay,
@@ -85,11 +119,20 @@ func NewHTTPPoetClient(baseUrl string, cfg PoetConfig, opts ...PoetClientOpts) (
 	poetClient := &HTTPPoetClient{
 		baseURL: baseURL,
 		client:  client,
+		logger:  zap.NewNop(),
 	}
 	for _, opt := range opts {
 		opt(poetClient)
 	}
 
+	poetClient.logger.Info(
+		"created poet client",
+		zap.Stringer("url", baseURL),
+		zap.Int("max retries", client.RetryMax),
+		zap.Duration("min retry wait", client.RetryWaitMin),
+		zap.Duration("max retry wait", client.RetryWaitMax),
+	)
+
 	return poetClient, nil
 }
 
@@ -211,8 +254,9 @@ func (c *HTTPPoetClient) req(ctx context.Context, method, path string, reqBody,
 		return fmt.Errorf("reading response body (%w)", err)
 	}
 
-	log.GetLogger().WithContext(ctx).With().Debug("response from poet", log.String("status", res.Status), log.String("body", string(data)))
-
+	if res.StatusCode != http.StatusOK {
+		c.logger.Info("got poet response != 200 OK", zap.String("status", res.Status), zap.String("body", string(data)))
+	}
 	switch res.StatusCode {
 	case http.StatusOK:
 	case http.StatusNotFound:

activation/poet_test.go

@@ -9,6 +9,7 @@ import (
 	"testing"
 
 	"github.com/stretchr/testify/require"
+	"go.uber.org/zap/zaptest"
 	"golang.org/x/sync/errgroup"
 
 	"github.com/spacemeshos/go-spacemesh/common/types"
@@ -29,22 +30,25 @@ func TestHTTPPoet(t *testing.T) {
 
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
-	c, err := NewHTTPPoetTestHarness(ctx, poetDir, DefaultPoetConfig())
+	c, err := NewHTTPPoetTestHarness(ctx, poetDir)
 	r.NoError(err)
 	r.NotNil(c)
 
 	eg.Go(func() error {
 		return c.Service.Start(ctx)
 	})
 
+	client, err := NewHTTPPoetClient(c.RestURL().String(), DefaultPoetConfig(), WithLogger(zaptest.NewLogger(t)))
+	require.NoError(t, err)
+
 	signer, err := signing.NewEdSigner(signing.WithPrefix([]byte("prefix")))
 	require.NoError(t, err)
 	ch := types.RandomHash()
 
 	signature := signer.Sign(signing.POET, ch.Bytes())
 	prefix := bytes.Join([][]byte{signer.Prefix(), {byte(signing.POET)}}, nil)
 
-	poetRound, err := c.Submit(context.Background(), prefix, ch.Bytes(), signature, signer.NodeID(), PoetPoW{})
+	poetRound, err := client.Submit(context.Background(), prefix, ch.Bytes(), signature, signer.NodeID(), PoetPoW{})
 	r.NoError(err)
 	r.NotNil(poetRound)
 }

activation/poet_test_harness.go

@@ -13,10 +13,16 @@ import (
 // HTTPPoetTestHarness utilizes a local self-contained poet server instance
 // targeted by an HTTP client. It is intended to be used in tests only.
 type HTTPPoetTestHarness struct {
-	*HTTPPoetClient
 	Service *server.Server
 }
 
+func (h *HTTPPoetTestHarness) RestURL() *url.URL {
+	return &url.URL{
+		Scheme: "http",
+		Host:   h.Service.GrpcRestProxyAddr().String(),
+	}
+}
+
 type HTTPPoetOpt func(*config.Config)
 
 func WithGenesis(genesis time.Time) HTTPPoetOpt {
@@ -44,7 +50,7 @@ func WithCycleGap(gap time.Duration) HTTPPoetOpt {
 }
 
 // NewHTTPPoetTestHarness returns a new instance of HTTPPoetHarness.
-func NewHTTPPoetTestHarness(ctx context.Context, poetdir string, clientCfg PoetConfig, opts ...HTTPPoetOpt) (*HTTPPoetTestHarness, error) {
+func NewHTTPPoetTestHarness(ctx context.Context, poetdir string, opts ...HTTPPoetOpt) (*HTTPPoetTestHarness, error) {
 	cfg := config.DefaultConfig()
 	cfg.PoetDir = poetdir
 	cfg.RawRESTListener = "localhost:0"
@@ -64,21 +70,7 @@ func NewHTTPPoetTestHarness(ctx context.Context, poetdir string, clientCfg PoetC
 		return nil, err
 	}
 
-	// NewHTTPPoetClient takes an URL as connection string. Server speaks HTTP.
-	url := &url.URL{
-		Scheme: "http",
-		Host:   poet.GrpcRestProxyAddr().String(),
-	}
-
-	client, err := NewHTTPPoetClient(url.String(), clientCfg)
-	if err != nil {
-		return nil, err
-	}
-
-	// TODO: query for the REST address to allow dynamic port allocation.
-	// It needs changes in poet.
 	return &HTTPPoetTestHarness{
-		HTTPPoetClient: client,
-		Service:        poet,
+		Service: poet,
 	}, nil
 }