Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

authz: add additional logs to sdk authz #5094

Merged
merged 8 commits into from Feb 18, 2022
Merged

authz: add additional logs to sdk authz #5094

Changes from 4 commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
f94882c
Adds additional logs to sdk authz
ashithasantosh Dec 28, 2021
16be6b7
resolve comment
ashithasantosh Jan 7, 2022
70237f0
adds logs displaying request details
ashithasantosh Jan 11, 2022
57186fb
remove sdk_server_interceptor log
ashithasantosh Jan 12, 2022
d0615bf
log subset of rpcData
ashithasantosh Feb 10, 2022
6a59149
Merge remote-tracking branch 'upstream/master' into add_logs
ashithasantosh Feb 15, 2022
f9afb06
resolving comment
ashithasantosh Feb 15, 2022
555e913
format log message
ashithasantosh Feb 18, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
3 changes: 3 additions & 0 deletions internal/xds/rbac/rbac_engine.go
View file
Open in desktop
Expand Up @@ -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) {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

logger.Infof("checking request: %v", rpcData)
}
for _, engine := range cre.chainedEngines {
matchingPolicyName, ok := engine.findMatchingPolicy(rpcData)
if logger.V(logLevel) && ok {
ashithasantosh marked this conversation as resolved.
Show resolved Hide resolved
Expand Down