More consistent tracing attributes and codes.

attestantio · Mar 26, 2024 · d3cd64e · d3cd64e
1 parent e8558f6
commit d3cd64e
Show file tree

Hide file tree

Showing 2 changed files with 120 additions and 29 deletions.
diff --git 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
@@ -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,13 +132,15 @@ 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()
 	req, err := http.NewRequestWithContext(opCtx, http.MethodPost, url.String(), body)
 	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,45 +331,59 @@ 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 {
 		// For now, assume that unknown type is JSON.
 		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{