Reduce noise in validator logs (#5307)

* Reduce number of info-level messages on start of validator

* Test service, not log entry

* Gazelle

Co-authored-by: Nishant Das <nishdas93@gmail.com>
Co-authored-by: Ivan Martinez <ivanthegreatdev@gmail.com>

shared/prometheus/BUILD.bazel

@@ -28,8 +28,6 @@ go_test(
     embed = [":go_default_library"],
     deps = [
         "//shared:go_default_library",
-        "//shared/testutil:go_default_library",
         "@com_github_sirupsen_logrus//:go_default_library",
-        "@com_github_sirupsen_logrus//hooks/test:go_default_library",
     ],
 )

shared/prometheus/service.go

@@ -4,9 +4,11 @@ import (
 	"bytes"
 	"context"
 	"fmt"
+	"net"
 	"net/http"
 	"runtime/debug"
 	"runtime/pprof"
+	"strings"
 	"time"
 
 	"github.com/prometheus/client_golang/prometheus/promhttp"
@@ -96,12 +98,22 @@ func (s *Service) goroutinezHandler(w http.ResponseWriter, _ *http.Request) {
 
 // Start the prometheus service.
 func (s *Service) Start() {
-	log.WithField("endpoint", s.server.Addr).Info("Collecting metrics at endpoint")
 	go func() {
-		err := s.server.ListenAndServe()
-		if err != nil && err != http.ErrServerClosed {
-			log.Errorf("Could not listen to host:port :%s: %v", s.server.Addr, err)
-			s.failStatus = err
+		// See if the port is already used.
+		addrParts := strings.Split(s.server.Addr, ":")
+		conn, err := net.DialTimeout("tcp", fmt.Sprintf("127.0.0.1:%s", addrParts[1]), time.Second)
+		if err == nil {
+			conn.Close()
+			// Something on the port; we cannot use it.
+			log.WithField("address", s.server.Addr).Warn("Port already in use; cannot start prometheus service")
+		} else {
+			// Nothing on that port; we can use it.
+			log.WithField("address", s.server.Addr).Debug("Starting prometheus service")
+			err := s.server.ListenAndServe()
+			if err != nil && err != http.ErrServerClosed {
+				log.Errorf("Could not listen to host:port :%s: %v", s.server.Addr, err)
+				s.failStatus = err
+			}
 		}
 	}()
 }

shared/prometheus/service_test.go

@@ -6,21 +6,35 @@ import (
 	"net/http/httptest"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/prysmaticlabs/prysm/shared"
-	"github.com/prysmaticlabs/prysm/shared/testutil"
-	logTest "github.com/sirupsen/logrus/hooks/test"
 )
 
 func TestLifecycle(t *testing.T) {
-	hook := logTest.NewGlobal()
 	prometheusService := NewPrometheusService(":2112", nil)
-
 	prometheusService.Start()
+	// Give service time to start.
+	time.Sleep(time.Second)
 
-	testutil.AssertLogsContain(t, hook, "Collecting metrics")
+	// Query the service to ensure it really started.
+	resp, err := http.Get("http://localhost:2112/metrics")
+	if err != nil {
+		t.Fatalf("Unexpected error: %v", err)
+	}
+	if resp.ContentLength == 0 {
+		t.Error("Unexpected content length 0")
+	}
 
 	prometheusService.Stop()
+	// Give service time to stop.
+	time.Sleep(time.Second)
+
+	// Query the service to ensure it really stopped.
+	_, err = http.Get("http://localhost:2112/metrics")
+	if err == nil {
+		t.Fatal("Service still running after Stop()")
+	}
 }
 
 type mockService struct {

shared/service_registry.go

@@ -38,7 +38,7 @@ func NewServiceRegistry() *ServiceRegistry {
 
 // StartAll initialized each service in order of registration.
 func (s *ServiceRegistry) StartAll() {
-	log.Infof("Starting %d services: %v", len(s.serviceTypes), s.serviceTypes)
+	log.Debugf("Starting %d services: %v", len(s.serviceTypes), s.serviceTypes)
 	for _, kind := range s.serviceTypes {
 		log.Debugf("Starting service type %v", kind)
 		go s.services[kind].Start()

validator/client/service.go

@@ -101,12 +101,14 @@ func (v *ValidatorService) Start() {
 
 	md := make(metadata.MD)
 	for _, hdr := range v.grpcHeaders {
-		ss := strings.Split(hdr, "=")
-		if len(ss) != 2 {
-			log.Warnf("Incorrect gRPC header flag format. Skipping %v", hdr)
-			continue
+		if hdr != "" {
+			ss := strings.Split(hdr, "=")
+			if len(ss) != 2 {
+				log.Warnf("Incorrect gRPC header flag format. Skipping %v", hdr)
+				continue
+			}
+			md.Set(ss[0], ss[1])
 		}
-		md.Set(ss[0], ss[1])
 	}
 
 	opts := []grpc.DialOption{
@@ -134,7 +136,7 @@ func (v *ValidatorService) Start() {
 		log.Errorf("Could not dial endpoint: %s, %v", v.endpoint, err)
 		return
 	}
-	log.Info("Successfully started gRPC connection")
+	log.Debug("Successfully started gRPC connection")
 
 	pubkeys, err := v.keyManager.FetchValidatingKeys()
 	if err != nil {

validator/node/node.go

@@ -80,7 +80,7 @@ func NewValidatorClient(ctx *cli.Context) (*ValidatorClient, error) {
 		if len(pubKeys) == 0 {
 			log.Warn("No keys found; nothing to validate")
 		} else {
-			log.WithField("validators", len(pubKeys)).Info("Found validator keys")
+			log.WithField("validators", len(pubKeys)).Debug("Found validator keys")
 			for _, key := range pubKeys {
 				log.WithField("pubKey", fmt.Sprintf("%#x", key)).Info("Validating for public key")
 			}