Improve SVID signing logs with more context #2678
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
rturner3
requested review from
amartinezfayo,
azdagron and
evan2645
as code owners
rturner3
force-pushed
the
improve-svid-signing-logs
branch
from
8d7f0db
to
f2822d4
Compare
The Server CA component currently uses a subsystem logger and logs when any SVID signing event happens. This logger is independent of the rpccontext logger, so it doesn't have any information about what event caused the SVID to be logged or by whom (i.e. caller details). In practice, these current log entries don't provide enough information to be very useful since the SVID cannot be traced back to an agent or an admin caller and have no common "trace" or request ID associated with other log entries. Rather than logging in the CA, log in the callers of the CA. Apart from X.509 CA SVID rotation, all SVID signings should come from an RPC context, so use the rpccontext logger in those cases. For X.509 CA SVID rotation, use the existing subsystem logger in the SVID rotator component. Signed-off-by: Ryan Turner <turner@uber.com>
rturner3
force-pushed
the
improve-svid-signing-logs
branch
from
f2822d4
to
e5d4c43
Compare
|
Some example logs with these changes for an agent attested with a join token with SPIFFE ID {
"expiration": "2022-01-12T02:36:01Z",
"level": "debug",
"msg": "Signed X509 SVID",
"spiffe_id": "spiffe://example.org/spire/server",
"subsystem_name": "svid_rotator",
"time": "2022-01-11T17:36:01-08:00"
}
{
"caller_addr": "127.0.0.1:58967",
"caller_id": "spiffe://example.org/spire/agent/join_token/1549be7e-d25b-4c75-9930-8c5b0d7a0317",
"entry_id": "2e7ebdd5-a5dd-4332-8e62-30341a08375b",
"expiration": "2022-01-12T02:36:09Z",
"level": "debug",
"method": "BatchNewX509SVID",
"msg": "Signed X509 SVID",
"request_id": "6ac138a2-de78-4f97-9c86-2c9fdbc7bc09",
"service": "svid.v1.SVID",
"spiffe_id": "spiffe://example.org/agent/foo",
"subsystem_name": "api",
"time": "2022-01-11T17:36:09-08:00"
}
{
"caller_addr": "127.0.0.1:58967",
"caller_id": "spiffe://example.org/spire/agent/join_token/1549be7e-d25b-4c75-9930-8c5b0d7a0317",
"entry_id": "2a20ccbb-f8b2-4271-ad13-4d7e73ca8293",
"expiration": "2022-01-12T02:36:43Z",
"level": "debug",
"method": "BatchNewX509SVID",
"msg": "Signed X509 SVID",
"request_id": "eaf8a255-4b82-4600-9f74-f9fd5bf02a49",
"service": "svid.v1.SVID",
"spiffe_id": "spiffe://example.org/schedulers/foo",
"subsystem_name": "api",
"time": "2022-01-11T17:36:43-08:00"
} |
MarcosDY
reviewed
Jan 12, 2022
added 2 commits
January 13, 2022 11:27
Signed-off-by: Ryan Turner <turner@uber.com>
azdagron
reviewed
Jan 14, 2022
| log.WithFields(logrus.Fields{ | ||
| telemetry.Audience: audience, | ||
| telemetry.Expiration: expiresAt.Format(time.RFC3339), | ||
| }).Debug("Server CA successfully signed JWT SVID") |
There was a problem hiding this comment.
Wonder if we shouldn't take this opportunity to change this log line to be consistent with the others?
Suggested change
| }).Debug("Server CA successfully signed JWT SVID") | |
| }).Debug("Signed JWT SVID") |
There was a problem hiding this comment.
I guess I feel inclined to keep the message the same as it is today since the proposed change in wording is semantically equivalent. I would prefer to err on the side of preserving the existing message text that users are already familiar with to prevent potentially breaking any log-based alerting.
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
The Server CA component currently uses a subsystem logger and logs when any SVID signing event happens. This logger is independent of the rpccontext logger, so it doesn't have any information about what event caused the SVID to be logged or by whom (i.e. caller details). In practice, these current log entries don't provide enough information to be very useful since the SVID cannot be traced back to an agent or an admin caller and have no common "trace" or request ID associated with other log entries.
Rather than logging in the CA, log in the callers of the CA. Apart from X.509 CA SVID rotation, all SVID signings should come from an RPC context, so use the rpccontext logger in those cases. For X.509 CA SVID rotation, use the existing subsystem logger in the SVID rotator component.