diff --git a/CHANGELOG.md b/CHANGELOG.md index a233662c..d5dc9cf7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,8 @@ +0.21.1: + - fix potential crash when unmarshaling Gwei values + - add `WithReducedMemoryUsage()` option for http service + - more consistent tracing attributes and codes + 0.21.0: - use v3 of the endpoint to obtain proposals - add bounds checking for ValidatorState diff --git a/http/http.go b/http/http.go index 99e5b57b..96235e19 100644 --- a/http/http.go +++ b/http/http.go @@ -30,6 +30,7 @@ import ( "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/trace" ) // post sends an HTTP post request and returns the body. @@ -77,7 +78,8 @@ func (s *Service) post(ctx context.Context, endpoint string, body io.Reader) (io statusFamily := resp.StatusCode / 100 if statusFamily != 2 { - log.Trace().Int("status_code", resp.StatusCode).Str("data", string(data)).Msg("POST failed") + log.Debug().Int("status_code", resp.StatusCode).Str("data", string(data)).Msg("POST failed") + s.monitorPostComplete(ctx, url.Path, "failed") return nil, &api.Error{ @@ -105,9 +107,12 @@ func (s *Service) post2(ctx context.Context, contentType ContentType, headers map[string]string, ) ( - io.Reader, + *httpResponse, error, ) { + ctx, span := otel.Tracer("attestantio.go-eth2-client.http").Start(ctx, "post") + defer span.End() + // #nosec G404 log := s.log.With().Str("id", fmt.Sprintf("%02x", rand.Int31())).Str("address", s.address).Str("endpoint", endpoint).Logger() if e := log.Trace(); e.Enabled() { @@ -127,6 +132,7 @@ func (s *Service) post2(ctx context.Context, url := urlForCall(s.base, endpoint, query) log.Trace().Str("url", url.String()).Msg("URL to POST") + span.SetAttributes(attribute.String("url", url.String())) opCtx, cancel := context.WithTimeout(ctx, s.timeout) defer cancel() @@ -134,6 +140,7 @@ func (s *Service) post2(ctx context.Context, if err != nil { return nil, errors.Join(errors.New("failed to create POST request"), err) } + s.addExtraHeaders(req) req.Header.Set("Content-Type", contentType.MediaType()) // Always take response of POST in JSON, as it's generally small. @@ -147,35 +154,91 @@ func (s *Service) post2(ctx context.Context, resp, err := s.client.Do(req) if err != nil { - go s.CheckConnectionState(ctx) + switch { + case errors.Is(err, context.Canceled): + // We don't consider context canceled to be a potential connection issue, as the user canceled the context. + case errors.Is(err, context.DeadlineExceeded): + // We don't consider context deadline exceeded to be a potential connection issue, as the user selected the deadline. + default: + // We consider other errors to be potential connection issues. + go s.CheckConnectionState(ctx) + } + + span.SetStatus(codes.Error, err.Error()) s.monitorPostComplete(ctx, url.Path, "failed") return nil, errors.Join(errors.New("failed to call POST endpoint"), err) } defer resp.Body.Close() + log = log.With().Int("status_code", resp.StatusCode).Logger() - data, err := io.ReadAll(resp.Body) + res := &httpResponse{ + statusCode: resp.StatusCode, + } + populateHeaders(res, resp) + + res.body, err = io.ReadAll(resp.Body) if err != nil { + switch { + case errors.Is(err, context.Canceled): + // We don't consider context canceled to be worth logging, as the user canceled the context. + case errors.Is(err, context.DeadlineExceeded): + // We don't consider context deadline exceeded to be worth logging, as the user selected the deadline. + default: + log.Warn().Err(err).Msg("Failed to read POST response") + } + + span.SetStatus(codes.Error, err.Error()) + s.monitorPostComplete(ctx, url.Path, "failed") + return nil, errors.Join(errors.New("failed to read POST response"), err) } + if resp.StatusCode == http.StatusNoContent { + // Nothing returned. This is not considered an error. + span.AddEvent("Received empty response") + log.Trace().Msg("Endpoint returned no content") + s.monitorPostComplete(ctx, url.Path, "succeeded") + + return res, nil + } + + if err := populateContentType(res, resp); err != nil { + // For now, assume that unknown type is JSON. + log.Debug().Err(err).Msg("Failed to obtain content type; assuming JSON") + res.contentType = ContentTypeJSON + } + span.AddEvent("Received response", trace.WithAttributes( + attribute.Int("size", len(res.body)), + attribute.String("content-type", res.contentType.String()), + )) + + if res.contentType == ContentTypeJSON { + trimmedResponse := bytes.ReplaceAll(bytes.ReplaceAll(res.body, []byte{0x0a}, []byte{}), []byte{0x0d}, []byte{}) + if e := log.Trace(); e.Enabled() { + e.RawJSON("body", trimmedResponse).Msg("POST response") + } + } + statusFamily := resp.StatusCode / 100 if statusFamily != 2 { - log.Trace().Int("status_code", resp.StatusCode).Str("data", string(data)).Msg("POST failed") + trimmedResponse := bytes.ReplaceAll(bytes.ReplaceAll(res.body, []byte{0x0a}, []byte{}), []byte{0x0d}, []byte{}) + log.Debug().Int("status_code", resp.StatusCode).RawJSON("response", trimmedResponse).Msg("POST failed") + + span.SetStatus(codes.Error, fmt.Sprintf("Status code %d", resp.StatusCode)) s.monitorPostComplete(ctx, url.Path, "failed") return nil, &api.Error{ Method: http.MethodPost, StatusCode: resp.StatusCode, Endpoint: endpoint, - Data: data, + Data: res.body, } } - log.Trace().Str("response", string(data)).Msg("POST response") s.monitorPostComplete(ctx, url.Path, "succeeded") - return bytes.NewReader(data), nil + return res, nil } func (s *Service) addExtraHeaders(req *http.Request) { @@ -197,9 +260,15 @@ type httpResponse struct { body []byte } -// get sends an HTTP get request and returns the body. -// If the response from the server is a 404 this will return nil for both the reader and the error. -func (s *Service) get(ctx context.Context, endpoint string, query string, opts *api.CommonOpts) (*httpResponse, error) { +// get sends an HTTP get request and returns the response. +func (s *Service) get(ctx context.Context, + endpoint string, + query string, + opts *api.CommonOpts, +) ( + *httpResponse, + error, +) { ctx, span := otel.Tracer("attestantio.go-eth2-client.http").Start(ctx, "get") defer span.End() @@ -209,6 +278,7 @@ func (s *Service) get(ctx context.Context, endpoint string, query string, opts * url := urlForCall(s.base, endpoint, query) log.Trace().Str("url", url.String()).Msg("URL to GET") + span.SetAttributes(attribute.String("url", url.String())) timeout := s.timeout if opts.Timeout != 0 { @@ -219,6 +289,8 @@ func (s *Service) get(ctx context.Context, endpoint string, query string, opts * defer cancel() req, err := http.NewRequestWithContext(opCtx, http.MethodGet, url.String(), nil) if err != nil { + span.SetStatus(codes.Error, "Failed to create request") + return nil, errors.Join(errors.New("failed to create GET request"), err) } @@ -237,7 +309,7 @@ func (s *Service) get(ctx context.Context, endpoint string, query string, opts * case errors.Is(err, context.Canceled): // We don't consider context canceled to be a potential connection issue, as the user canceled the context. case errors.Is(err, context.DeadlineExceeded): - // We don't consider context deadline exceeded to be a potential connection issue, as the user selected the deadline. + // We don't consider context deadline exceeded to be a potential connection issue, as the user selected the deadline. case strings.HasSuffix(url.String(), "/node/syncing"): // Special case; if we have called the syncing endpoint and it failed then we don't check the connectino status, as // that calls the syncing endpoint itself and so we find ourselves in an endless loop. @@ -246,7 +318,7 @@ func (s *Service) get(ctx context.Context, endpoint string, query string, opts * go s.CheckConnectionState(ctx) } - span.RecordError(errors.New("request failed")) + span.SetStatus(codes.Error, err.Error()) s.monitorGetComplete(ctx, url.Path, "failed") return nil, errors.Join(errors.New("failed to call GET endpoint"), err) @@ -259,25 +331,34 @@ func (s *Service) get(ctx context.Context, endpoint string, query string, opts * } populateHeaders(res, resp) - if resp.StatusCode == http.StatusNoContent { - // Nothing returned. This is not considered an error. - span.AddEvent("Received empty response") - log.Trace().Msg("Endpoint returned no content") - s.monitorGetComplete(ctx, url.Path, "failed") - - return res, nil - } - // Although it would be more efficient to keep the body as a Reader, that would - // require the calling function to be aware that it needs to clode the body + // require the calling function to be aware that it needs to close the body // once it is done with it. To avoid that complexity, we read here and store the // body as a byte array. res.body, err = io.ReadAll(resp.Body) if err != nil { - span.RecordError(err) - log.Warn().Err(err).Msg("Failed to read body") + switch { + case errors.Is(err, context.Canceled): + // We don't consider context canceled to be worth logging, as the user canceled the context. + case errors.Is(err, context.DeadlineExceeded): + // We don't consider context deadline exceeded to be worth logging, as the user selected the deadline. + default: + log.Warn().Err(err).Msg("Failed to read GET response") + } - return nil, errors.Join(errors.New("failed to read body"), err) + span.SetStatus(codes.Error, err.Error()) + s.monitorGetComplete(ctx, url.Path, "failed") + + return nil, errors.Join(errors.New("failed to read GET response"), err) + } + + if resp.StatusCode == http.StatusNoContent { + // Nothing returned. This is not considered an error. + span.AddEvent("Received empty response") + log.Trace().Msg("Endpoint returned no content") + s.monitorGetComplete(ctx, url.Path, "succeeded") + + return res, nil } if err := populateContentType(res, resp); err != nil { @@ -285,19 +366,24 @@ func (s *Service) get(ctx context.Context, endpoint string, query string, opts * log.Debug().Err(err).Msg("Failed to obtain content type; assuming JSON") res.contentType = ContentTypeJSON } - span.SetAttributes(attribute.String("content-type", res.contentType.String())) + span.AddEvent("Received response", trace.WithAttributes( + attribute.Int("size", len(res.body)), + attribute.String("content-type", res.contentType.String()), + )) if res.contentType == ContentTypeJSON { + trimmedResponse := bytes.ReplaceAll(bytes.ReplaceAll(res.body, []byte{0x0a}, []byte{}), []byte{0x0d}, []byte{}) if e := log.Trace(); e.Enabled() { - e.RawJSON("body", res.body).Msg("Response") + e.RawJSON("body", trimmedResponse).Msg("GET response") } } statusFamily := resp.StatusCode / 100 if statusFamily != 2 { - span.SetStatus(codes.Error, fmt.Sprintf("Status code %d", resp.StatusCode)) trimmedResponse := bytes.ReplaceAll(bytes.ReplaceAll(res.body, []byte{0x0a}, []byte{}), []byte{0x0d}, []byte{}) log.Debug().Int("status_code", resp.StatusCode).RawJSON("response", trimmedResponse).Msg("GET failed") + + span.SetStatus(codes.Error, fmt.Sprintf("Status code %d", resp.StatusCode)) s.monitorGetComplete(ctx, url.Path, "failed") return nil, &api.Error{