update logging in prober (#499)

* update logging in prober

Signed-off-by: Bob Callaway <[email protected]>

* update to use new cmd line args for timestamp-cli

Signed-off-by: Bob Callaway <[email protected]>

* fix one additional timestamp-cli call

Signed-off-by: Bob Callaway <[email protected]>

Signed-off-by: Bob Callaway <[email protected]>

.github/workflows/fulcio-rekor-kind.yaml

@@ -213,7 +213,7 @@ jobs:
           echo "failed to timestamp artifact"
           exit -1
         fi
-        if ! ./timestamp-cli verify --timestamp response.tsr --artifact "myblob" --cert-chain ts_chain.pem ; then
+        if ! ./timestamp-cli verify --timestamp response.tsr --artifact "myblob" --certificate-chain ts_chain.pem ; then
           echo "failed to verify timestamp"
           exit -1
         fi

.github/workflows/prober-test.yml

@@ -30,4 +30,4 @@ jobs:
 
       - name: Prober test
         id: prober-test
-        run: go run ./cmd/prober --one-time --write-prober
+        run: go run ./cmd/prober --one-time --write-prober --logStyle dev

.github/workflows/test-action-tuf.yaml

@@ -102,7 +102,7 @@ jobs:
           echo "failed to timestamp artifact"
           exit -1
         fi
-        if ! ./timestamp-cli verify --timestamp response.tsr --artifact "myblob" --cert-chain ts_chain.pem ; then
+        if ! ./timestamp-cli verify --timestamp response.tsr --artifact "myblob" --certificate-chain ts_chain.pem ; then
           echo "failed to verify timestamp"
           exit -1
         fi

.github/workflows/test-release.yaml

@@ -151,7 +151,7 @@ jobs:
           echo "failed to timestamp artifact"
           exit -1
         fi
-        if ! ./timestamp-cli verify --timestamp response.tsr --artifact "myblob" --cert-chain ts_chain.pem ; then
+        if ! ./timestamp-cli verify --timestamp response.tsr --artifact "myblob" --certificate-chain ts_chain.pem ; then
           echo "failed to verify timestamp"
           exit -1
         fi

.gitignore

@@ -5,3 +5,4 @@ release-*.yaml
 testrelease.yaml
 kind.yaml
 .vscode/*
+prober

cmd/prober/prober.go

@@ -19,7 +19,6 @@ import (
 	"context"
 	"encoding/json"
 	"flag"
-	"fmt"
 	"log"
 	"net/http"
 	"os"
@@ -32,9 +31,67 @@ import (
 	"sigs.k8s.io/release-utils/version"
 
 	_ "github.com/sigstore/cosign/pkg/providers/all"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 )
 
+var retryableClient *retryablehttp.Client
+
+type proberLogger struct {
+	*zap.SugaredLogger
+}
+
+func (p proberLogger) Printf(msg string, args ...interface{}) {
+	p.Infof(msg, args...)
+}
+
+var Logger proberLogger
+
+func ConfigureLogger(location string) {
+	cfg := zap.NewProductionConfig()
+	switch location {
+	case "prod":
+		cfg.EncoderConfig.LevelKey = "severity"
+		cfg.EncoderConfig.MessageKey = "message"
+		cfg.EncoderConfig.TimeKey = "time"
+		cfg.EncoderConfig.EncodeLevel = encodeLevel()
+		cfg.EncoderConfig.EncodeTime = zapcore.RFC3339TimeEncoder
+		cfg.EncoderConfig.EncodeDuration = zapcore.MillisDurationEncoder
+		cfg.EncoderConfig.EncodeCaller = zapcore.ShortCallerEncoder
+	default:
+		cfg = zap.NewDevelopmentConfig()
+		cfg.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
+	}
+	logger, err := cfg.Build()
+	if err != nil {
+		log.Fatalln("createLogger", err)
+	}
+	Logger = proberLogger{logger.Sugar()}
+}
+
+func encodeLevel() zapcore.LevelEncoder {
+	return func(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) {
+		switch l {
+		case zapcore.DebugLevel:
+			enc.AppendString("DEBUG")
+		case zapcore.InfoLevel:
+			enc.AppendString("INFO")
+		case zapcore.WarnLevel:
+			enc.AppendString("WARNING")
+		case zapcore.ErrorLevel:
+			enc.AppendString("ERROR")
+		case zapcore.DPanicLevel:
+			enc.AppendString("CRITICAL")
+		case zapcore.PanicLevel:
+			enc.AppendString("ALERT")
+		case zapcore.FatalLevel:
+			enc.AppendString("EMERGENCY")
+		}
+	}
+}
+
 var (
+	logStyle       string
 	frequency      int
 	retries        uint
 	addr           string
@@ -45,8 +102,11 @@ var (
 	versionInfo    version.Info
 )
 
+type attemptCtxKey string
+
 func init() {
 	flag.IntVar(&frequency, "frequency", 10, "How often to run probers (in seconds)")
+	flag.StringVar(&logStyle, "logStyle", "prod", "log style to use (dev or prod)")
 	flag.StringVar(&addr, "addr", ":8080", "Port to expose prometheus to")
 
 	flag.StringVar(&rekorURL, "rekor-url", "https://rekor.sigstore.dev", "Set to the Rekor URL to run probers against")
@@ -65,6 +125,20 @@ func init() {
 
 	flag.Parse()
 
+	ConfigureLogger(logStyle)
+	retryableClient = retryablehttp.NewClient()
+	retryableClient.Logger = Logger
+	retryableClient.RetryMax = int(retries)
+	retryableClient.RequestLogHook = func(_ retryablehttp.Logger, r *http.Request, attempt int) {
+		ctx := context.WithValue(r.Context(), attemptCtxKey("attempt_number"), attempt)
+		*r = *r.WithContext(ctx)
+		Logger.Infof("attempt #%d for %v %v", attempt, r.Method, r.URL)
+	}
+	retryableClient.ResponseLogHook = func(_ retryablehttp.Logger, r *http.Response) {
+		attempt := r.Request.Context().Value(attemptCtxKey("attempt_number"))
+		Logger.With(zap.Int("bytes", int(r.ContentLength))).Infof("attempt #%d result: %d", attempt, r.StatusCode)
+	}
+
 	var rekorFlagRequests []ReadProberCheck
 	if err := json.Unmarshal([]byte(rekorRequestsJSON), &rekorFlagRequests); err != nil {
 		log.Fatal("Failed to parse rekor-requests: ", err)
@@ -82,7 +156,7 @@ func init() {
 func main() {
 	ctx := context.Background()
 	versionInfo = version.GetVersionInfo()
-	fmt.Printf("running create_ct_config Version: %s GitCommit: %s BuildDate: %s", versionInfo.GitVersion, versionInfo.GitCommit, versionInfo.BuildDate)
+	Logger.Infof("running prober Version: %s GitCommit: %s BuildDate: %s", versionInfo.GitVersion, versionInfo.GitCommit, versionInfo.BuildDate)
 
 	reg := prometheus.NewRegistry()
 	reg.MustRegister(endpointLatenciesSummary, endpointLatenciesHistogram, verificationCounter)
@@ -98,9 +172,9 @@ func main() {
 			EnableOpenMetrics: true,
 		},
 	))
-	fmt.Printf("Starting Server on port %s", addr)
+	Logger.Infof("Starting Prometheus Server on port %s", addr)
 	/* #nosec G114 */
-	log.Fatal(http.ListenAndServe(addr, nil))
+	Logger.Fatal(http.ListenAndServe(addr, nil))
 }
 
 func runProbers(ctx context.Context, freq int, runOnce bool) {
@@ -110,32 +184,31 @@ func runProbers(ctx context.Context, freq int, runOnce bool) {
 		for _, r := range RekorEndpoints {
 			if err := observeRequest(rekorURL, r); err != nil {
 				hasErr = true
-				fmt.Printf("error running request %s: %v\n", r.Endpoint, err)
+				Logger.Errorf("error running request %s: %v", r.Endpoint, err)
 			}
 		}
 		for _, r := range FulcioEndpoints {
 			if err := observeRequest(fulcioURL, r); err != nil {
 				hasErr = true
-				fmt.Printf("error running request %s: %v\n", r.Endpoint, err)
+				Logger.Errorf("error running request %s: %v", r.Endpoint, err)
 			}
 		}
 		if runWriteProber {
 			if err := fulcioWriteEndpoint(ctx); err != nil {
 				hasErr = true
-				fmt.Printf("error running fulcio write prober: %v\n", err)
+				Logger.Errorf("error running fulcio write prober: %v", err)
 			}
 			if err := rekorWriteEndpoint(ctx); err != nil {
 				hasErr = true
-				fmt.Printf("error running rekor write prober: %v\n", err)
+				Logger.Errorf("error running rekor write prober: %v", err)
 			}
 		}
 
 		if runOnce {
 			if hasErr {
-				fmt.Println("Failed")
-				os.Exit(1)
+				Logger.Fatal("Failed")
 			} else {
-				fmt.Println("Complete")
+				Logger.Info("Complete")
 				os.Exit(0)
 			}
 		}
@@ -145,16 +218,13 @@ func runProbers(ctx context.Context, freq int, runOnce bool) {
 }
 
 func observeRequest(host string, r ReadProberCheck) error {
-	client := retryablehttp.NewClient()
-	client.RetryMax = int(retries)
-
 	req, err := httpRequest(host, r)
 	if err != nil {
 		return err
 	}
 
 	s := time.Now()
-	resp, err := client.Do(req)
+	resp, err := retryableClient.Do(req)
 	latency := time.Since(s).Milliseconds()
 
 	if err != nil {

cmd/prober/prometheus.go

@@ -17,8 +17,10 @@ package main
 import (
 	"fmt"
 	"net/http"
+	"time"
 
 	"github.com/prometheus/client_golang/prometheus"
+	"go.uber.org/zap"
 )
 
 var (
@@ -67,9 +69,7 @@ func exportDataToPrometheus(resp *http.Response, host, endpoint, method string,
 	endpointLatenciesSummary.With(labels).Observe(float64(latency))
 	endpointLatenciesHistogram.With(labels).Observe(float64(latency))
 
-	fmt.Println("Observing ", method, host+endpoint)
-	fmt.Println("Status code: ", statusCode)
-	fmt.Printf("Latency for %s %s: %d\n", method, host+endpoint, latency)
+	Logger.With(zap.Int("status", statusCode), zap.Int("bytes", int(resp.ContentLength)), zap.Duration("latency", time.Duration(latency)*time.Millisecond)).Infof("[DEBUG] %v %v", method, host+endpoint)
 }
 
 // NewVersionCollector returns a collector that exports metrics about current version

cmd/prober/write.go

@@ -93,12 +93,11 @@ func fulcioWriteEndpoint(ctx context.Context) error {
 	setHeaders(req, tok)
 
 	t := time.Now()
-	retryableClient := retryablehttp.NewClient()
-	retryableClient.RetryMax = int(retries)
 	resp, err := retryableClient.Do(req)
 	latency := time.Since(t).Milliseconds()
 	if err != nil {
-		fmt.Printf("error requesting cert: %v\n", err.Error())
+		Logger.Errorf("error requesting cert: %v", err)
+		return err
 	}
 	defer resp.Body.Close()
 
@@ -125,8 +124,6 @@ func rekorWriteEndpoint(ctx context.Context) error {
 	setHeaders(req, "")
 
 	t := time.Now()
-	retryableClient := retryablehttp.NewClient()
-	retryableClient.RetryMax = int(retries)
 	resp, err := retryableClient.Do(req)
 	latency := time.Since(t).Milliseconds()
 	if err != nil {

go.mod

@@ -23,6 +23,7 @@ require (
 	github.com/sigstore/timestamp-authority v0.1.3
 	github.com/theupdateframework/go-tuf v0.5.2-0.20220930112810-3890c1e7ace4
 	github.com/titanous/rocacheck v0.0.0-20171023193734-afe73141d399
+	go.uber.org/zap v1.24.0
 	golang.org/x/crypto v0.3.0
 	google.golang.org/genproto v0.0.0-20221111202108-142d8a6fa32e
 	google.golang.org/grpc v1.51.0
@@ -209,7 +210,6 @@ require (
 	go.step.sm/crypto v0.23.1 // indirect
 	go.uber.org/atomic v1.10.0 // indirect
 	go.uber.org/multierr v1.8.0 // indirect
-	go.uber.org/zap v1.24.0 // indirect
 	golang.org/x/exp v0.0.0-20220823124025-807a23277127 // indirect
 	golang.org/x/mod v0.6.0 // indirect
 	golang.org/x/net v0.2.0 // indirect