From 900f5b5275c23a250ebd0f283578b95a2c519096 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartosz=20R=C3=B3=C5=BCa=C5=84ski?= Date: Fri, 8 Sep 2023 20:08:10 +0000 Subject: [PATCH] 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 | 1 + activation/nipost.go | 2 +- activation/nipost_test.go | 31 +++++++++--------- activation/poet.go | 56 +++++++++++++++++++++++++++++---- activation/poet_test.go | 8 +++-- activation/poet_test_harness.go | 26 ++++++--------- 6 files changed, 82 insertions(+), 42 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 03ceabb39b..e3183e69d1 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/activation/nipost.go b/activation/nipost.go index 4f2aa71a1d..74e6c388b5 100644 --- a/activation/nipost.go +++ b/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) } diff --git a/activation/nipost_test.go b/activation/nipost_test.go index fd8ed5a677..92b502e190 100644 --- a/activation/nipost_test.go +++ b/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,7 +203,7 @@ 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) @@ -209,14 +211,13 @@ func buildNIPost(tb testing.TB, postProvider *testPostManager, nipostChallenge t 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) diff --git a/activation/poet.go b/activation/poet.go index 6e2376fd4e..5d86d72749 100644 --- a/activation/poet.go +++ b/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: diff --git a/activation/poet_test.go b/activation/poet_test.go index 5c77f1158a..7145820165 100644 --- a/activation/poet_test.go +++ b/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,7 +30,7 @@ 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) @@ -37,6 +38,9 @@ func TestHTTPPoet(t *testing.T) { 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() @@ -44,7 +48,7 @@ func TestHTTPPoet(t *testing.T) { 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) } diff --git a/activation/poet_test_harness.go b/activation/poet_test_harness.go index 29c9b7c3b5..83108ecfdb 100644 --- a/activation/poet_test_harness.go +++ b/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 }