chore: log requests upon retrieval (#1140)

Author: RTann

api/grpc/grpc.go

@@ -145,7 +145,8 @@ func WithDefaultInterceptors() ConfigOpts {
 	return func(cfg *Config) {
 		// Interceptors are executed in order.
 		cfg.UnaryInterceptors = []grpc.UnaryServerInterceptor{
-			// Ensure the user is authorized before doing anything else.
+			loggingUnaryServerInterceptor(),
+			// Ensure the user is authorized before doing anything other than logging.
 			verifyPeerCertsUnaryServerInterceptor(),
 			slimModeUnaryServerInterceptor(),
 			grpcprometheus.UnaryServerInterceptor,

api/grpc/logging_interceptor.go

@@ -0,0 +1,29 @@
+package grpc
+
+import (
+	"context"
+	"fmt"
+	"time"
+
+	"github.com/sirupsen/logrus"
+	"google.golang.org/grpc"
+)
+
+func loggingUnaryServerInterceptor() grpc.UnaryServerInterceptor {
+	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
+		logrus.WithFields(map[string]interface{}{
+			"URI": info.FullMethod,
+		}).Infof("Received gRPC request")
+
+		start := time.Now()
+		resp, err := handler(ctx, req)
+		duration := fmt.Sprintf("%f seconds", time.Since(start).Seconds())
+
+		logrus.WithFields(map[string]interface{}{
+			"URI":      info.FullMethod,
+			"Duration": duration,
+		}).Infof("Finished gRPC request")
+
+		return resp, err
+	}
+}

api/v1/imagescan/service.go

@@ -203,11 +203,19 @@ func (s *serviceImpl) getImageComponents(_ context.Context, req *v1.GetImageComp
 }
 
 func (s *serviceImpl) GetImageVulnerabilities(_ context.Context, req *v1.GetImageVulnerabilitiesRequest) (*v1.GetImageVulnerabilitiesResponse, error) {
+	imageName := "unknown"
+	if req.GetImage() != "" {
+		imageName = req.GetImage()
+	}
+	logrus.Infof("Fetching vulnerabilities for %s", imageName)
+
 	layer, err := apiV1.GetVulnerabilitiesForComponents(s.db, req.GetComponents(), common.HasUncertifiedRHEL(req.GetNotes()))
 	if err != nil {
 		return nil, status.Error(codes.Internal, err.Error())
 	}
 
+	logrus.Infof("Done fetching vulnerabilities for %s", imageName)
+
 	return &v1.GetImageVulnerabilitiesResponse{
 		ScannerVersion: s.version,
 		Status:         v1.ScanStatus_SUCCEEDED,

e2etests/grpc_full_test.go

@@ -184,6 +184,7 @@ func TestGRPCGetImageVulnerabilities(t *testing.T) {
 		// This test assumes TestGRPCGetImageComponents passes, so there is no need to check the component response.
 
 		vulnsResp, err := client.GetImageVulnerabilities(context.Background(), &v1.GetImageVulnerabilitiesRequest{
+			Image:      testCase.image,
 			Components: imgComponentsResp.GetComponents(),
 			Notes:      imgComponentsResp.GetNotes(),
 		})

generated/scanner/api/v1/image_scan_service.pb.go

@@ -0,0 +1,44 @@
+// Note: there is no gRPC equivalent to this, as this is, instead,
+// captured upon calling ServeHTTP in api/grpc/grpc.go.
+
+package middleware
+
+import (
+	"fmt"
+	"net/http"
+	"time"
+
+	"github.com/gorilla/mux"
+	"github.com/sirupsen/logrus"
+	"github.com/stackrox/rox/pkg/httputil"
+)
+
+// Log returns middleware which logs basic information about the incoming HTTP request.
+func Log() mux.MiddlewareFunc {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			logrus.WithFields(map[string]interface{}{
+				"Method": r.Method,
+				"URI":    r.URL.String(),
+			}).Infof("Received HTTP request from %s", r.RemoteAddr)
+
+			stw := httputil.NewStatusTrackingWriter(w)
+
+			start := time.Now()
+			next.ServeHTTP(stw, r)
+			duration := fmt.Sprintf("%f seconds", time.Since(start).Seconds())
+
+			var statusCode int
+			if code := stw.GetStatusCode(); code != nil {
+				statusCode = *code
+			}
+
+			logrus.WithFields(map[string]interface{}{
+				"Method":   r.Method,
+				"URI":      r.URL.String(),
+				"Duration": duration,
+				"Status":   statusCode,
+			}).Infof("Finished HTTP request from %s", r.RemoteAddr)
+		})
+	}
+}

pkg/clairify/server/middleware/log.go

@@ -213,11 +213,14 @@ func (s *Server) ScanImage(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	logrus.Infof("Start processing image %v", image)
 	_, err = server.ProcessImage(s.storage, image, imageRequest.Registry, username, password, imageRequest.Insecure, imageRequest.UncertifiedRHELScan)
 	if err != nil {
+		logrus.Infof("End processing image %v: failure", image)
 		clairErrorString(w, http.StatusInternalServerError, "error processing image %q: %v", imageRequest.Image, err)
 		return
 	}
+	logrus.Infof("End processing image %v: success", image)
 	imageEnvelope := types.ImageEnvelope{
 		ScannerVersion: s.version,
 		Image:          image,
@@ -277,7 +280,8 @@ func (s *Server) Start() error {
 	r := mux.NewRouter()
 	// Middlewares are executed in order.
 	r.Use(
-		// Ensure the user is authorized before doing anything else.
+		middleware.Log(),
+		// Ensure the user is authorized before doing anything other than logging.
 		middleware.VerifyPeerCerts(),
 		middleware.SlimMode(),
 	)

pkg/clairify/server/server.go

@@ -56,7 +56,9 @@ message GetImageComponentsResponse {
     repeated Note notes           = 3;
 }
 
+// Next tag: 4
 message GetImageVulnerabilitiesRequest {
+    string        image      = 3;
     Components    components = 1;
     repeated Note notes      = 2;
 }