ROX-17438: improve infra (audit) logging (#949)

auth/handlers.go

@@ -71,12 +71,14 @@ func (a OidcAuth) loginHandler(w http.ResponseWriter, r *http.Request) {
 // profile is then obtained from OIDC provider that includes details about the
 // newly logged-in user. This user information is then stored in a cookie.
 func (a OidcAuth) callbackHandler(w http.ResponseWriter, r *http.Request) {
+	logPhase := "auth-callback"
+
 	// Get the value of the "state" HTTP GET param, and validate that it is
 	// legitimate.
 	stateToken := r.URL.Query().Get("state")
 	err := a.jwtState.Validate(stateToken)
 	if err != nil {
-		log.Errorw("failed to validate state token", "error", err)
+		log.AuditLog(logging.ERROR, logPhase, "failed to validate state token", "error", err)
 		http.Redirect(w, r, "/logout", http.StatusTemporaryRedirect)
 		return
 	}
@@ -85,13 +87,13 @@ func (a OidcAuth) callbackHandler(w http.ResponseWriter, r *http.Request) {
 	code := r.URL.Query().Get("code")
 	rawToken, err := a.conf.Exchange(r.Context(), code)
 	if err != nil {
-		log.Errorw("failed to exchange code", "error", err)
+		log.AuditLog(logging.ERROR, logPhase, "failed to exchange code", "error", err)
 		http.Redirect(w, r, "/logout", http.StatusTemporaryRedirect)
 		return
 	}
 
 	if err := a.jwtAccess.Validate(r.Context(), rawToken); err != nil {
-		log.Errorw("failed to validate access token", "err", err)
+		log.AuditLog(logging.ERROR, logPhase, "failed to validate access token", "err", err)
 		http.Redirect(w, r, "/logout", http.StatusTemporaryRedirect)
 		return
 	}
@@ -100,15 +102,15 @@ func (a OidcAuth) callbackHandler(w http.ResponseWriter, r *http.Request) {
 	// user struct from it.
 	user, err := a.jwtOidc.Validate(r.Context(), rawToken)
 	if err != nil {
-		log.Errorw("failed to validate ID token", "error", err)
+		log.AuditLog(logging.ERROR, logPhase, "failed to validate ID token", "error", err)
 		http.Redirect(w, r, "/logout", http.StatusTemporaryRedirect)
 		return
 	}
 
 	// Generate token containing a user struct.
 	userToken, err := a.jwtUser.Generate(user)
 	if err != nil {
-		log.Errorw("failed to generate user token", "error", err)
+		log.AuditLog(logging.ERROR, logPhase, "failed to generate user token", "error", err)
 		http.Redirect(w, r, "/logout", http.StatusTemporaryRedirect)
 		return
 	}

auth/tokenizer.go

@@ -11,6 +11,7 @@ import (
 	"github.com/pkg/errors"
 	"github.com/stackrox/infra/auth/claimrule"
 	v1 "github.com/stackrox/infra/generated/api/v1"
+	"github.com/stackrox/infra/pkg/logging"
 	"golang.org/x/oauth2"
 )
 
@@ -124,13 +125,19 @@ type oidcClaims struct {
 func (c oidcClaims) Valid() error {
 	_, isExcluded := excludedEmails[c.Email]
 	if isExcluded {
-		return errors.New("email address is excluded")
+		errMsg := "email address is excluded"
+		log.AuditLog(logging.INFO, "oidc-claim-validation", errMsg, "email", c.Email)
+		return errors.New(errMsg)
 	}
 	switch {
 	case !c.EmailVerified:
-		return errors.New("email address is not verified")
+		errMsg := "email address is not verified"
+		log.AuditLog(logging.INFO, "oidc-claim-validation", errMsg, "email", c.Email)
+		return errors.New(errMsg)
 	case !strings.HasSuffix(c.Email, emailSuffixRedHat):
-		return errors.Errorf("%q email address does not belong to Red Hat", c.Email)
+		errMsg := "email address does not belong to Red Hat"
+		log.AuditLog(logging.INFO, "oidc-claim-validation", errMsg, "email", c.Email)
+		return errors.Errorf(errMsg)
 	default:
 		c.StandardClaims.IssuedAt -= clockDriftLeeway
 		valid := c.StandardClaims.Valid()
@@ -265,6 +272,7 @@ func (t serviceAccountTokenizer) Generate(svcacct v1.ServiceAccount) (string, er
 
 	// Ensure that our service account is well-formed.
 	if err := svc.Valid(); err != nil {
+		log.AuditLog(logging.INFO, "service-account-validation", err.Error(), "email", svc.Email)
 		return "", errors.Wrap(err, "invalid service account")
 	}
 

bqutil/client.go

@@ -64,14 +64,14 @@ type clusterDeletionRecord struct {
 // NewClient returns a new BigQuery client
 func NewClient(cfg *config.BigQueryConfig) (BigQueryClient, error) {
 	if os.Getenv("TEST_MODE") == "true" {
-		log.Infow("disabling BigQuery integration because we are in TEST_MODE")
+		log.Log(logging.INFO, "disabling BigQuery integration because we are in TEST_MODE")
 		return &disabledClient{}, nil
 	}
 
 	// If the config was missing a BigQuery configuration, disable the integration
 	// altogether.
 	if cfg == nil {
-		log.Infow("disabling BigQuery integration due to missing configuration")
+		log.Log(logging.INFO, "disabling BigQuery integration due to missing configuration")
 		return &disabledClient{}, nil
 	}
 
@@ -92,7 +92,7 @@ func NewClient(cfg *config.BigQueryConfig) (BigQueryClient, error) {
 		deletionInserter: deletionInserter,
 	}
 
-	log.Infow("enabled BigQuery integration")
+	log.Log(logging.INFO, "enabled BigQuery integration")
 
 	return bigQueryClient, nil
 }

cmd/infra-server/main.go

@@ -47,7 +47,7 @@ func mainCmd() error {
 	}
 
 	log := logging.CreateProductionLogger()
-	log.Infow("starting infra server", "version", buildinfo.All().Version)
+	log.Log(logging.INFO, "starting infra server", "version", buildinfo.All().Version)
 
 	serverConfigFile := filepath.Join(*flagConfigDir, "infra.yaml")
 	cfg, err := config.Load(serverConfigFile)

flavor/registry.go

@@ -73,7 +73,7 @@ func (r *Registry) add(flavor v1.Flavor, workflow v1alpha1.Workflow) error {
 		workflow: workflow,
 		flavor:   flavor,
 	}
-	log.Infow("registered flavor", "flavor-id", flavor.GetID(), "flavor-name", flavor.GetName())
+	log.Log(logging.INFO, "registered flavor", "flavor-id", flavor.GetID(), "flavor-name", flavor.GetName())
 
 	// Register a default flavor if one has not already been registered.
 	if flavor.Availability == v1.Flavor_default {
@@ -82,7 +82,7 @@ func (r *Registry) add(flavor v1.Flavor, workflow v1alpha1.Workflow) error {
 			return fmt.Errorf("both %q and %q configured as default flavors", r.defaultFlavor, flavor.ID)
 		}
 		r.defaultFlavor = flavor.ID
-		log.Infow("registered default flavor", "flavor-id", flavor.GetID(), "flavor-name", flavor.GetName())
+		log.Log(logging.INFO, "registered default flavor", "flavor-id", flavor.GetID(), "flavor-name", flavor.GetName())
 	}
 
 	return nil

flavor/workflow_templates.go

@@ -10,6 +10,7 @@ import (
 	workflowtemplatepkg "github.com/argoproj/argo-workflows/v3/pkg/apiclient/workflowtemplate"
 	"github.com/argoproj/argo-workflows/v3/pkg/apis/workflow/v1alpha1"
 	v1 "github.com/stackrox/infra/generated/api/v1"
+	"github.com/stackrox/infra/pkg/logging"
 )
 
 func (r *Registry) initWorkflowTemplatesClient() error {
@@ -32,7 +33,7 @@ func (r *Registry) addWorkflowTemplates(results []v1.Flavor) []v1.Flavor {
 		Namespace: r.workflowTemplateNamespace,
 	})
 	if err != nil {
-		log.Errorw("failed to list argo workflow templates", "error", err)
+		log.Log(logging.ERROR, "failed to list argo workflow templates", "error", err)
 		return results
 	}
 
@@ -63,7 +64,7 @@ func (r *Registry) getPairFromWorkflowTemplate(id string) (*v1.Flavor, *v1alpha1
 			Namespace: r.workflowTemplateNamespace,
 		})
 		if err != nil {
-			log.Warnw("failed to get an argo workflow template", "id", id, "error", err)
+			log.Log(logging.WARN, "failed to get an argo workflow template", "id", id, "error", err)
 			return nil, nil
 		}
 		r.workflowTemplateCache[id] = template
@@ -87,7 +88,7 @@ func (r *Registry) getPairFromWorkflowTemplate(id string) (*v1.Flavor, *v1alpha1
 func workflowTemplate2Flavor(template *v1alpha1.WorkflowTemplate) *v1.Flavor {
 	valid := true
 	if template.ObjectMeta.Annotations["infra.stackrox.io/description"] == "" {
-		log.Warnw("ignoring a workflow template without infra.stackrox.io/description annotation",
+		log.Log(logging.WARN, "ignoring a workflow template without infra.stackrox.io/description annotation",
 			"template-name", template.GetObjectMeta().GetName(),
 		)
 		valid = false
@@ -96,7 +97,7 @@ func workflowTemplate2Flavor(template *v1alpha1.WorkflowTemplate) *v1.Flavor {
 	if template.ObjectMeta.Annotations["infra.stackrox.io/availability"] != "" {
 		value, ok := v1.FlavorAvailability_value[template.ObjectMeta.Annotations["infra.stackrox.io/availability"]]
 		if !ok {
-			log.Warnw("ignoring a workflow template with an unknown infra.stackrox.io/availability annotation",
+			log.Log(logging.WARN, "ignoring a workflow template with an unknown infra.stackrox.io/availability annotation",
 				"template-name", template.GetObjectMeta().GetName(),
 				"template-availability", template.GetObjectMeta().GetAnnotations()["infra.stackrox.io/availability"],
 			)
@@ -106,7 +107,7 @@ func workflowTemplate2Flavor(template *v1alpha1.WorkflowTemplate) *v1.Flavor {
 	}
 	for _, wfParameter := range template.Spec.Arguments.Parameters {
 		if wfParameter.Description == nil {
-			log.Warnw("ignoring a workflow template with a parameter that has no description",
+			log.Log(logging.WARN, "ignoring a workflow template with a parameter that has no description",
 				"template-name", template.GetObjectMeta().GetName(),
 				"parameter", wfParameter.Name,
 			)
@@ -134,7 +135,7 @@ func getParametersFromWorkflowTemplate(template *v1alpha1.WorkflowTemplate) map[
 
 	for idx, wfParameter := range template.Spec.Arguments.Parameters {
 		if wfParameter.Description == nil {
-			log.Warnw("ignoring a workflow template with a parameter that has no description",
+			log.Log(logging.WARN, "ignoring a workflow template with a parameter that has no description",
 				"template-name", template.GetObjectMeta().GetName(),
 				"parameter", wfParameter.Name,
 			)

pkg/logging/logger.go

@@ -7,6 +7,23 @@ import (
 	"go.uber.org/zap"
 )
 
+// LogLevel enumerates log levels
+type LogLevel int
+
+const (
+	// DEBUG is the equivalent of zap.DebugLevel
+	DEBUG LogLevel = iota
+
+	// INFO is the equivalent of zap.InfoLevel
+	INFO
+
+	// WARN is the equivalent of zap.WarnLevel
+	WARN
+
+	// ERROR is the equivalent of zap.ErrorLevel
+	ERROR
+)
+
 // Logger wraps a zap.SugaredLogger.
 type Logger struct {
 	*zap.SugaredLogger
@@ -53,3 +70,26 @@ func CreateProductionLogger() *Logger {
 func CreateDevelopmentLogger() *Logger {
 	return createLogger(DevelopmentLogger)
 }
+
+// Log is a prepared wrapper to harmonize the logging entrypoint.
+func (l *Logger) Log(logLevel LogLevel, msg string, keysAndValues ...interface{}) {
+	var method func(msg string, keysAndValues ...interface{})
+	switch logLevel {
+	case DEBUG:
+		method = l.Debugw
+	case INFO:
+		method = l.Infow
+	case WARN:
+		method = l.Warnw
+	case ERROR:
+		method = l.Errorw
+	}
+
+	method(msg, keysAndValues...)
+}
+
+// AuditLog is a prepared wrapper to harmonize the audit logging format.
+func (l *Logger) AuditLog(logLevel LogLevel, phase string, msg string, keysAndValues ...interface{}) {
+	keysAndValues = append(keysAndValues, "log-type", "audit", "phase", phase)
+	l.Log(logLevel, msg, keysAndValues...)
+}

server/server.go

@@ -99,7 +99,7 @@ func (s *server) RunServer() (<-chan error, error) {
 		mux.ServeHTTP(w, r)
 	})
 
-	log.Infow("starting gRPC server", "listen-address", listenAddress)
+	log.Log(logging.INFO, "starting gRPC server", "listen-address", listenAddress)
 	go func() {
 		if err := http.ListenAndServeTLS(listenAddress, s.cfg.Server.CertFile, s.cfg.Server.KeyFile, h2c.NewHandler(muxHandler, &http2.Server{})); err != nil {
 			errCh <- err
@@ -111,7 +111,7 @@ func (s *server) RunServer() (<-chan error, error) {
 		return nil, err
 	}
 
-	log.Infow("starting gRPC-Gateway client", "connect-address", connectAddress)
+	log.Log(logging.INFO, "starting gRPC-Gateway client", "connect-address", connectAddress)
 	conn, err := grpc.Dial(connectAddress, dialOption)
 	if err != nil {
 		return nil, errors.Wrap(err, "dialing gRPC")

service/cli.go

@@ -32,14 +32,14 @@ func NewCliService() (middleware.APIService, error) {
 // Upgrade provides the binary for the requested OS and architecture.
 func (s *cliImpl) Upgrade(request *v1.CliUpgradeRequest, stream v1.CliService_UpgradeServer) error {
 	if err := platform.Validate(request.GetOs(), request.GetArch()); err != nil {
-		log.Infow("failed to validate platform for infractl upgrade", "error", err)
+		log.Log(logging.INFO, "failed to validate platform for infractl upgrade", "error", err)
 		return err
 	}
 
 	filename := webRoot + "/downloads/infractl-" + request.GetOs() + "-" + request.GetArch()
 	file, err := os.Open(filename)
 	if err != nil {
-		log.Errorw("failed to open infractl binary", "error", err)
+		log.Log(logging.ERROR, "failed to open infractl binary", "error", err)
 		return err
 	}
 	defer file.Close()
@@ -50,12 +50,12 @@ func (s *cliImpl) Upgrade(request *v1.CliUpgradeRequest, stream v1.CliService_Up
 			break
 		}
 		if err != nil {
-			log.Errorw("error while reading infractl chunk", "error", err)
+			log.Log(logging.ERROR, "error while reading infractl chunk", "error", err)
 			return err
 		}
 		resp := &v1.CliUpgradeResponse{FileChunk: buff[:bytesRead]}
 		if err := stream.Send(resp); err != nil {
-			log.Errorw("error while sending infractl chunk", "error", err)
+			log.Log(logging.ERROR, "error while sending infractl chunk", "error", err)
 			return err
 		}
 	}