authz: add additional logs to sdk authz #5094

ashithasantosh · 2021-12-28T21:14:07Z

These logs will be useful for debugging.

RELEASE NOTES:

authz: adds additional logs to sdk authz

authz/sdk_server_interceptors.go

ashithasantosh · 2022-01-07T20:00:06Z

Thank you for the review!:)

ashithasantosh · 2022-01-12T00:20:17Z

internal/xds/rbac/rbac_engine.go

@@ -77,6 +77,9 @@ func (cre *ChainEngine) IsAuthorized(ctx context.Context) error {
 		logger.Errorf("newRPCData: %v", err)
 		return status.Errorf(codes.Internal, "gRPC RBAC: %v", err)
 	}
+	if logger.V(logLevel) {


@dfawley
The logs will display details about incoming request.
This could be helpful for our users (ex. Brixia) in debugging, like why a particular request was rejected when it should have been allowed.

This is similar to Envoy RBAC
https://github.com/envoyproxy/envoy/blob/53f95570a7e9d7fa5414a4bc145852524fa017ed/source/extensions/filters/http/rbac/rbac_filter.cc#L51
And implemented in C++ too (in SDK filter)
https://github.com/grpc/grpc/blob/master/src/core/lib/security/authorization/sdk_server_authz_filter.cc#L96

This would be very helpful in debugging bugs like https://buganizer.corp.google.com/issues/211707413

We need to be cautious about logging any RPC data; it could potentially expose PII. Being at verbosity 2 might make it acceptable, though. What are we doing in other languages?

We have similar logging at debug level in C++
https://github.com/grpc/grpc/blob/master/src/core/lib/security/authorization/sdk_server_authz_filter.cc#L96

Java is in early stages of implementation.

I agree we should be cautious about logging RPC data.
Adding @yihuazhang for insights.

I agree we should not log arbitrary RPC data at the server side because it can potentially cause privacy incident if a server e.g., is misconfigured to allow anyone to read its log. It is a common practice for a server to log denied authz requests, but it is for the auditing purpose, instead of debugging bugs. If a client wants to know why his RPC is denied, he should get it through a different channel, which should be access controlled as well.

@ejona86 @markdroth Please let me know your thoughts on logging RPC information.

This is logging a function? s/newRPCData/rpcData/ ?

Java is in early stages of implementation.

This change is in the rbac engine which is complete, not the TODO authz API. In Java we have a log for the authz result: "no matches" or the rule name that matches. We do not log by default; it is a debug log level. Our rule is "no logs by default", which we do break a few times, but they are rare "something is horribly broken" circumstances.

rpcData looks helpful to dump, but really only appropriate at lower log levels. It has the full metadata, which can lots of things you don't want to log normally. The log messages themselves will be very large.

I'll note that newRPCData() modifies the metadata returned by metadata.FromIncomingContext(), but that method doesn't define whether it returns a copy. It looks like its behavior changed recently in 32d5490 to make a copy without saying it is a copy. I guess the docs need to be updated there, otherwise newRPCData() is very sketchy.

Long-term, there will need to be a reporting feature for xDS authz (sometimes called "shadow rules") so that you can try out new rules before enforcing them. We could expose an API to enable such things in authz API as well. But even there, there's so many things the authz rules can inspect it seems inappropriate to log it all and yes, that causes serious problems for debuggability.

We are logging rpcData here. I had planned to change that to specific values within struct - SANs and subject field in leaf certificate and url path (these fields were requested by Brixia)

Yes, I agree we definitely shouldn't log by default. In C++ we are logging rpc data at debug level when sdk_authz trace is enabled. In Go we are logging at verbosity level 2. The main concern here is exposing PII, which I think SANs are (not sure!). Else we could have logged just the fields required by Brixia (mentioned above).

C++: https://github.com/grpc/grpc/blob/master/src/core/lib/security/authorization/sdk_server_authz_filter.cc#L96

Logging payload/metadata at verbosity 2 is probably fine, so I'm ok with this modulo my other comment re: eliminating logLevel.

Thank you for the discussion. I updated the PR to log just the fields requested by Brixia (url path, SANs and Subject) and only for denied requests. PTAL.

internal/xds/rbac/rbac_engine.go

authz/sdk_server_interceptors.go

dfawley · 2022-01-12T18:14:44Z

internal/xds/rbac/rbac_engine.go

@@ -77,6 +77,9 @@ func (cre *ChainEngine) IsAuthorized(ctx context.Context) error {
 		logger.Errorf("newRPCData: %v", err)
 		return status.Errorf(codes.Internal, "gRPC RBAC: %v", err)
 	}
+	if logger.V(logLevel) {


We need to be cautious about logging any RPC data; it could potentially expose PII. Being at verbosity 2 might make it acceptable, though. What are we doing in other languages?

internal/xds/rbac/rbac_engine.go

github-actions · 2022-02-08T18:45:54Z

This PR is labeled as requiring an update from the reporter, and no update has been received after 6 days. If no update is provided in the next 7 days, this issue will be automatically closed.

easwars · 2022-02-09T19:15:39Z

@ashithasantosh : Is there any update on this PR?

ashithasantosh · 2022-02-10T01:16:40Z

@easwars Sorry for the delay. I updated the code and also replied to the pending comments.

internal/xds/rbac/rbac_engine.go

dfawley · 2022-02-18T00:05:44Z

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)


Nit: rejected: %v so it doesn't look like the error is a continuation of the same sentence. (and line 83)

Done. Thank you for the review!:)

internal/xds/rbac/rbac_engine.go

Adds additional logs to sdk authz

f94882c

ashithasantosh changed the title ~~Adds additional logs to sdk authz~~ authz: adds additional logs to sdk authz Dec 28, 2021

ashithasantosh added this to the 1.44 Release milestone Dec 28, 2021

ashithasantosh added the Type: Internal Cleanup Refactors, etc label Dec 28, 2021

ashithasantosh requested a review from dfawley December 28, 2021 21:16

menghanl reviewed Jan 5, 2022

View reviewed changes

authz/sdk_server_interceptors.go Outdated Show resolved Hide resolved

resolve comment

16be6b7

menghanl approved these changes Jan 7, 2022

View reviewed changes

menghanl assigned dfawley Jan 7, 2022

zasweq modified the milestones: 1.44 Release, 1.45 Release Jan 11, 2022

adds logs displaying request details

70237f0

ashithasantosh commented Jan 12, 2022

View reviewed changes

internal/xds/rbac/rbac_engine.go Outdated Show resolved Hide resolved

dfawley requested changes Jan 12, 2022

View reviewed changes

dfawley assigned ashithasantosh and unassigned dfawley Jan 12, 2022

remove sdk_server_interceptor log

57186fb

dfawley added the Status: Requires Reporter Clarification label Feb 1, 2022

dfawley changed the title ~~authz: adds additional logs to sdk authz~~ authz: add additional logs to sdk authz Feb 2, 2022

github-actions bot added the stale label Feb 8, 2022

github-actions bot removed the stale label Feb 9, 2022

log subset of rpcData

d0615bf

ashithasantosh removed the Status: Requires Reporter Clarification label Feb 10, 2022

dfawley reviewed Feb 15, 2022

View reviewed changes

internal/xds/rbac/rbac_engine.go Outdated Show resolved Hide resolved

internal/xds/rbac/rbac_engine.go Show resolved Hide resolved

Merge remote-tracking branch 'upstream/master' into add_logs

6a59149

resolving comment

f9afb06

zasweq assigned dfawley and unassigned ashithasantosh Feb 16, 2022

dfawley approved these changes Feb 18, 2022

View reviewed changes

dfawley assigned ashithasantosh and unassigned dfawley Feb 18, 2022

format log message

555e913

ashithasantosh merged commit 011544f into grpc:master Feb 18, 2022

github-actions bot locked as resolved and limited conversation to collaborators Aug 18, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

authz: add additional logs to sdk authz #5094

authz: add additional logs to sdk authz #5094

ashithasantosh commented Dec 28, 2021 •

edited

ashithasantosh commented Jan 7, 2022

ashithasantosh Jan 12, 2022 •

edited

ashithasantosh Jan 12, 2022 •

edited

dfawley Jan 12, 2022

ashithasantosh Jan 12, 2022

yihuazhang Jan 13, 2022

ashithasantosh Jan 19, 2022 •

edited

ejona86 Jan 19, 2022

ashithasantosh Jan 21, 2022

dfawley Jan 31, 2022

ashithasantosh Feb 10, 2022

dfawley Jan 12, 2022

github-actions bot commented Feb 8, 2022

easwars commented Feb 9, 2022

ashithasantosh commented Feb 10, 2022

dfawley Feb 18, 2022

ashithasantosh Feb 18, 2022

authz: add additional logs to sdk authz #5094

authz: add additional logs to sdk authz #5094

Conversation

ashithasantosh commented Dec 28, 2021 • edited

ashithasantosh commented Jan 7, 2022

ashithasantosh Jan 12, 2022 • edited

Choose a reason for hiding this comment

ashithasantosh Jan 12, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ashithasantosh Jan 19, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

github-actions bot commented Feb 8, 2022

easwars commented Feb 9, 2022

ashithasantosh commented Feb 10, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ashithasantosh commented Dec 28, 2021 •

edited

ashithasantosh Jan 12, 2022 •

edited

ashithasantosh Jan 12, 2022 •

edited

ashithasantosh Jan 19, 2022 •

edited