[#1574] container: Introduce debug logging for APE check failures

Signed-off-by: Airat Arifullin <a.arifullin@yadro.com>

cmd/frostfs-node/container.go

@@ -56,7 +56,7 @@ func initContainerService(_ context.Context, c *cfg) {
 	)
 	service := containerService.NewSignService(
 		&c.key.PrivateKey,
-		containerService.NewAPEServer(defaultChainRouter, cnrRdr,
+		containerService.NewAPEServer(c.log, defaultChainRouter, cnrRdr,
 			newCachedIRFetcher(createInnerRingFetcher(c)), c.netMapSource, c.shared.frostfsidClient,
 			containerService.NewSplitterService(
 				c.cfgContainer.containerBatchSize, c.respSvc,

pkg/services/container/ape.go

@@ -12,10 +12,13 @@ import (
 	"net"
 	"strings"
 
+	"git.frostfs.info/TrueCloudLab/frostfs-node/internal/logs"
 	aperequest "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/ape/request"
 	containercore "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/core/container"
 	frostfsidcore "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/core/frostfsid"
 	"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/core/netmap"
+	apecommon "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/common/ape"
+	"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger"
 	"git.frostfs.info/TrueCloudLab/frostfs-observability/tracing"
 	"git.frostfs.info/TrueCloudLab/frostfs-sdk-go/api/container"
 	"git.frostfs.info/TrueCloudLab/frostfs-sdk-go/api/refs"
@@ -31,6 +34,7 @@ import (
 	commonschema "git.frostfs.info/TrueCloudLab/policy-engine/schema/common"
 	nativeschema "git.frostfs.info/TrueCloudLab/policy-engine/schema/native"
 	"github.com/nspcc-dev/neo-go/pkg/crypto/keys"
+	"go.uber.org/zap"
 	"google.golang.org/grpc/peer"
 )
 
@@ -57,6 +61,7 @@ type containers interface {
 }
 
 type apeChecker struct {
+	logger *logger.Logger
 	router policyengine.ChainRouter
 	reader containers
 	ir     ir
@@ -67,8 +72,9 @@ type apeChecker struct {
 	next Server
 }
 
-func NewAPEServer(router policyengine.ChainRouter, reader containers, ir ir, nm netmap.Source, frostFSIDClient frostfsidcore.SubjectProvider, srv Server) Server {
+func NewAPEServer(logger *logger.Logger, router policyengine.ChainRouter, reader containers, ir ir, nm netmap.Source, frostFSIDClient frostfsidcore.SubjectProvider, srv Server) Server {
 	return &apeChecker{
+		logger:          logger,
 		router:          router,
 		reader:          reader,
 		ir:              ir,
@@ -172,7 +178,10 @@ func (ac *apeChecker) List(ctx context.Context, req *container.ListRequest) (*co
 		return ac.next.List(ctx, req)
 	}
 
-	return nil, apeErr(nativeschema.MethodListContainers, s)
+	chRouterErr := apecommon.NewChainRouterError(rt, request, s)
+	ac.logger.Debug(ctx, logs.APECheckDeniedRequest, zap.Object("details", chRouterErr))
+
+	return nil, apeErr(chRouterErr)
 }
 
 func (ac *apeChecker) ListStream(req *container.ListStreamRequest, stream ListStream) error {
@@ -245,7 +254,10 @@ func (ac *apeChecker) ListStream(req *container.ListStreamRequest, stream ListSt
 		return ac.next.ListStream(req, stream)
 	}
 
-	return apeErr(nativeschema.MethodListContainers, s)
+	chRouterErr := apecommon.NewChainRouterError(rt, request, s)
+	ac.logger.Debug(ctx, logs.APECheckDeniedRequest, zap.Object("details", chRouterErr))
+
+	return apeErr(chRouterErr)
 }
 
 func (ac *apeChecker) Put(ctx context.Context, req *container.PutRequest) (*container.PutResponse, error) {
@@ -318,7 +330,10 @@ func (ac *apeChecker) Put(ctx context.Context, req *container.PutRequest) (*cont
 		return ac.next.Put(ctx, req)
 	}
 
-	return nil, apeErr(nativeschema.MethodPutContainer, s)
+	chRouterErr := apecommon.NewChainRouterError(rt, request, s)
+	ac.logger.Debug(ctx, logs.APECheckDeniedRequest, zap.Object("details", chRouterErr))
+
+	return nil, apeErr(chRouterErr)
 }
 
 func (ac *apeChecker) getRoleWithoutContainerID(ctx context.Context, oID *refs.OwnerID, mh *session.RequestMetaHeader, vh *session.RequestVerificationHeader) (string, *keys.PublicKey, error) {
@@ -400,8 +415,9 @@ func (ac *apeChecker) validateContainerBoundedOperation(ctx context.Context, con
 		reqProps,
 	)
 
+	rt := policyengine.NewRequestTargetExtended(namespace, id.EncodeToString(), fmt.Sprintf("%s:%s", namespace, pk.Address()), groups)
 	s, found, err := ac.router.IsAllowed(apechain.Ingress,
-		policyengine.NewRequestTargetExtended(namespace, id.EncodeToString(), fmt.Sprintf("%s:%s", namespace, pk.Address()), groups),
+		rt,
 		request)
 	if err != nil {
 		return err
@@ -411,12 +427,15 @@ func (ac *apeChecker) validateContainerBoundedOperation(ctx context.Context, con
 		return nil
 	}
 
-	return apeErr(op, s)
+	chRouterErr := apecommon.NewChainRouterError(rt, request, s)
+	ac.logger.Debug(ctx, logs.APECheckDeniedRequest, zap.Object("details", chRouterErr))
+
+	return apeErr(chRouterErr)
 }
 
-func apeErr(operation string, status apechain.Status) error {
+func apeErr(err error) error {
 	errAccessDenied := &apistatus.ObjectAccessDenied{}
-	errAccessDenied.WriteReason(fmt.Sprintf("access to container operation %s is denied by access policy engine: %s", operation, status.String()))
+	errAccessDenied.WriteReason(err.Error())
 	return errAccessDenied
 }
 

pkg/services/container/ape_test.go

@@ -12,6 +12,7 @@ import (
 	"git.frostfs.info/TrueCloudLab/frostfs-contract/frostfsid/client"
 	containercore "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/core/container"
 	frostfsidcore "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/core/frostfsid"
+	"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger"
 	"git.frostfs.info/TrueCloudLab/frostfs-sdk-go/api/container"
 	"git.frostfs.info/TrueCloudLab/frostfs-sdk-go/api/refs"
 	session "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/api/session"
@@ -32,6 +33,7 @@ import (
 	"github.com/nspcc-dev/neo-go/pkg/crypto/keys"
 	"github.com/nspcc-dev/neo-go/pkg/util"
 	"github.com/stretchr/testify/require"
+	"go.uber.org/zap"
 	"google.golang.org/grpc/peer"
 )
 
@@ -85,7 +87,7 @@ func testAllowThenDenyGetContainerRuleDefined(t *testing.T) {
 	frostfsIDSubjectReader := &frostfsidStub{
 		subjects: map[util.Uint160]*client.Subject{},
 	}
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 
 	contID := cidtest.ID()
 	testContainer := containertest.Container()
@@ -184,7 +186,7 @@ func TestAllowByGroupIDs(t *testing.T) {
 			},
 		},
 	}
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 
 	contID := cidtest.ID()
 	testContainer := containertest.Container()
@@ -257,7 +259,7 @@ func testDenyGetContainerNoRuleFound(t *testing.T) {
 	frostfsIDSubjectReader := &frostfsidStub{
 		subjects: map[util.Uint160]*client.Subject{},
 	}
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 
 	contID := cidtest.ID()
 	testContainer := containertest.Container()
@@ -307,7 +309,7 @@ func testDenyGetContainerForOthers(t *testing.T) {
 	frostfsIDSubjectReader := &frostfsidStub{
 		subjects: map[util.Uint160]*client.Subject{},
 	}
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 
 	contID := cidtest.ID()
 	testContainer := containertest.Container()
@@ -407,7 +409,7 @@ func testDenyGetContainerByUserClaimTag(t *testing.T) {
 		},
 	}
 
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 
 	contID := cidtest.ID()
 	testContainer := containertest.Container()
@@ -505,7 +507,7 @@ func testDenyGetContainerByIP(t *testing.T) {
 		},
 	}
 
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 
 	contID := cidtest.ID()
 	testContainer := containertest.Container()
@@ -604,7 +606,7 @@ func testDenyGetContainerByGroupID(t *testing.T) {
 		},
 	}
 
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 
 	contID := cidtest.ID()
 	testContainer := containertest.Container()
@@ -684,7 +686,7 @@ func testDenyPutContainerForOthersSessionToken(t *testing.T) {
 			ownerAddr: {},
 		},
 	}
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 
 	nm.currentEpoch = 100
 	nm.netmaps = map[uint64]*netmap.NetMap{}
@@ -797,7 +799,7 @@ func testDenyPutContainerReadNamespaceFromFrostfsID(t *testing.T) {
 			},
 		},
 	}
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 	resp, err := apeSrv.Put(context.Background(), req)
 	require.Nil(t, resp)
 	var errAccessDenied *apistatus.ObjectAccessDenied
@@ -881,7 +883,7 @@ func testDenyPutContainerInvalidNamespace(t *testing.T) {
 			},
 		},
 	}
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 	resp, err := apeSrv.Put(context.Background(), req)
 	require.Nil(t, resp)
 	require.ErrorContains(t, err, "invalid domain zone")
@@ -903,7 +905,7 @@ func testDenyListContainersForPK(t *testing.T) {
 	frostfsIDSubjectReader := &frostfsidStub{
 		subjects: map[util.Uint160]*client.Subject{},
 	}
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 
 	nm.currentEpoch = 100
 	nm.netmaps = map[uint64]*netmap.NetMap{}
@@ -1020,7 +1022,7 @@ func testDenyListContainersValidationNamespaceError(t *testing.T) {
 		},
 	}
 
-	apeSrv := NewAPEServer(router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
+	apeSrv := NewAPEServer(logger.NewLoggerWrapper(zap.NewNop()), router, contRdr, ir, nm, frostfsIDSubjectReader, srv)
 
 	nm.currentEpoch = 100
 	nm.netmaps = map[uint64]*netmap.NetMap{}
@@ -1188,6 +1190,7 @@ func newTestAPEServer() testAPEServer {
 	}
 
 	apeChecker := &apeChecker{
+		logger:          logger.NewLoggerWrapper(zap.NewNop()),
 		router:          engine,
 		reader:          containerReader,
 		ir:              ir,
@@ -1247,8 +1250,8 @@ func TestValidateContainerBoundedOperation(t *testing.T) {
 		req := initTestGetContainerRequest(t, contID)
 
 		err = components.apeChecker.validateContainerBoundedOperation(ctxWithPeerInfo(), req.GetBody().GetContainerID(), req.GetMetaHeader(), req.GetVerificationHeader(), nativeschema.MethodGetContainer)
-		aErr := apeErr(nativeschema.MethodGetContainer, chain.AccessDenied)
+		var accessDeniedErr *apistatus.ObjectAccessDenied
-		require.ErrorContains(t, err, aErr.Error())
+		require.ErrorAs(t, err, &accessDeniedErr)
 	})
 
 	t.Run("check root-defined container in testdomain-defined container target rule", func(t *testing.T) {
@@ -1420,8 +1423,8 @@ func TestValidateContainerBoundedOperation(t *testing.T) {
 		req := initTestGetContainerRequest(t, contID)
 
 		err = components.apeChecker.validateContainerBoundedOperation(ctxWithPeerInfo(), req.GetBody().GetContainerID(), req.GetMetaHeader(), req.GetVerificationHeader(), nativeschema.MethodGetContainer)
-		aErr := apeErr(nativeschema.MethodGetContainer, chain.AccessDenied)
+		var accessDeniedErr *apistatus.ObjectAccessDenied
-		require.ErrorContains(t, err, aErr.Error())
+		require.ErrorAs(t, err, &accessDeniedErr)
 	})
 
 	t.Run("check testdomain-defined container in testdomain namespace target rule", func(t *testing.T) {
@@ -1462,8 +1465,8 @@ func TestValidateContainerBoundedOperation(t *testing.T) {
 		req := initTestGetContainerRequest(t, contID)
 
 		err = components.apeChecker.validateContainerBoundedOperation(ctxWithPeerInfo(), req.GetBody().GetContainerID(), req.GetMetaHeader(), req.GetVerificationHeader(), nativeschema.MethodGetContainer)
-		aErr := apeErr(nativeschema.MethodGetContainer, chain.AccessDenied)
+		var accessDeniedErr *apistatus.ObjectAccessDenied
-		require.ErrorContains(t, err, aErr.Error())
+		require.ErrorAs(t, err, &accessDeniedErr)
 	})
 }