authz: add additional logs to sdk authz (#5094)

* Adds additional logs to sdk authz

* resolve comment

* adds logs displaying request details

* remove sdk_server_interceptor log

* log subset of rpcData

* resolving comment

* format log message

authz/grpc_authz_server_interceptors.go

@@ -62,6 +62,9 @@ func (i *StaticInterceptor) UnaryInterceptor(ctx context.Context, req interface{
 	err := i.engines.IsAuthorized(ctx)
 	if err != nil {
 		if status.Code(err) == codes.PermissionDenied {
+			if logger.V(2) {
+				logger.Infof("unauthorized RPC request rejected: %v", err)
+			}
 			return nil, status.Errorf(codes.PermissionDenied, "unauthorized RPC request rejected")
 		}
 		return nil, err
@@ -76,6 +79,9 @@ func (i *StaticInterceptor) StreamInterceptor(srv interface{}, ss grpc.ServerStr
 	err := i.engines.IsAuthorized(ss.Context())
 	if err != nil {
 		if status.Code(err) == codes.PermissionDenied {
+			if logger.V(2) {
+				logger.Infof("unauthorized RPC request rejected: %v", err)
+			}
 			return status.Errorf(codes.PermissionDenied, "unauthorized RPC request rejected")
 		}
 		return err

internal/xds/rbac/rbac_engine.go

@@ -39,8 +39,6 @@ import (
 	"google.golang.org/grpc/status"
 )
 
-const logLevel = 2
-
 var logger = grpclog.Component("rbac")
 
 var getConnection = transport.GetConnection
@@ -65,6 +63,16 @@ func NewChainEngine(policies []*v3rbacpb.RBAC) (*ChainEngine, error) {
 	return &ChainEngine{chainedEngines: engines}, nil
 }
 
+func (cre *ChainEngine) logRequestDetails(rpcData *rpcData) {
+	if logger.V(2) {
+		logger.Infof("checking request: url path=%s", rpcData.fullMethod)
+		if len(rpcData.certs) > 0 {
+			cert := rpcData.certs[0]
+			logger.Infof("uri sans=%q, dns sans=%q, subject=%v", cert.URIs, cert.DNSNames, cert.Subject)
+		}
+	}
+}
+
 // IsAuthorized determines if an incoming RPC is authorized based on the chain of RBAC
 // engines and their associated actions.
 //
@@ -79,14 +87,16 @@ func (cre *ChainEngine) IsAuthorized(ctx context.Context) error {
 	}
 	for _, engine := range cre.chainedEngines {
 		matchingPolicyName, ok := engine.findMatchingPolicy(rpcData)
-		if logger.V(logLevel) && ok {
+		if logger.V(2) && ok {
 			logger.Infof("incoming RPC matched to policy %v in engine with action %v", matchingPolicyName, engine.action)
 		}
 
 		switch {
 		case engine.action == v3rbacpb.RBAC_ALLOW && !ok:
+			cre.logRequestDetails(rpcData)
 			return status.Errorf(codes.PermissionDenied, "incoming RPC did not match an allow policy")
 		case engine.action == v3rbacpb.RBAC_DENY && ok:
+			cre.logRequestDetails(rpcData)
 			return status.Errorf(codes.PermissionDenied, "incoming RPC matched a deny policy %q", matchingPolicyName)
 		}
 		// Every policy in the engine list must be queried. Thus, iterate to the