Implement structured logging for gRPC errors on SPIRE agent #4262

Neniel · 2023-06-15T12:12:38Z

Pull Request check list

Commit conforms to CONTRIBUTING.md?
Proper tests/regressions included?
Documentation updated?

Affected functionality

SPIRE agent's client

Description of change

This pull request is intended to improve logging of gRPC errors from the SPIRE agent by separating code and message.

Which issue this PR fixes

fixes #2613

rturner3

Thanks for sending this, @Neniel! I had a couple small suggestions, but overall this is headed in the right direction.

pkg/agent/client/client.go

MarcosDY · 2023-06-16T15:42:46Z

pkg/agent/client/client.go

@@ -171,7 +171,14 @@ func (c *client) RenewSVID(ctx context.Context, csr []byte) (*X509SVID, error) {
 	})
 	if err != nil {
 		c.release(connection)
-		c.c.Log.WithError(err).Error("Failed to renew agent")
+		log := c.c.Log
+		if s, ok := status.FromError(err); ok {


can you add a helper function to reduce code? (and use constants), something like:

func addErrorFields(log logrus.FieldLogger, err error) logrus.FieldLogger { if s, ok := status.FromError(err); ok { log = log.WithFields(logrus.Fields{ telemetry.StatusCode: s.Code(), telemetry.StatusMessage: s.Message(), }) } return log }

and you can call

log := addErrorFields(c.c.Log, err)

Yes, that's what I asked Taylor in a previous comment but I'm not sure where to create that function. Is there a helper package or something similar that is suitable to hold this kind of stuff?

add as private on the same file, or do you think you need to use in on different packages?

For now it will only be used on the same package.

Fixed on 6c8d983, let me know in case there's more suggestions :)

pkg/agent/client/client.go

rturner3 · 2023-06-22T20:23:31Z

pkg/agent/client/client_test.go

+			c := &client{
+				c: tt.fields.c,
+			}
+			assert.Equalf(t, tt.want, c.addErrorFields(tt.args.err), "addErrorFields(%v)", tt.args.err)


As addErrorFields() is a private method of client, I think it would be better to test that each public method in client produces the expected error logs when the RPCs those public methods call return errors. However, I acknowledge that would significantly increase the scope of this PR because there is no testing of log messages in this struct today. We do similar log assertions in other parts of the codebase, but it looks like it was missed in this package for some reason.

If you feel up for adding that test support, it would be much appreciated since there are currently uncovered branches, and it's a bit difficult to tell that the usages of this new method are working as expected. If not, I think it would be good to create a follow-up issue and link it as a comment somewhere in this file (maybe above each test that is covering error cases).

I've just started working on that. Please check 29961ed for the first tests that covers some cases. I'll be adding the remaining ones.

Please dismiss my previous comment, I need to re-write the tests due to the changes of the ex addErrorFields method.

I've just updated the new tests at 7d46273

rturner3 · 2023-06-22T20:25:05Z

pkg/agent/client/client.go

@@ -362,9 +362,9 @@ func (c *client) fetchBundles(ctx context.Context, federatedBundles []string) ([
 		case codes.OK:
 			bundles = append(bundles, bundle)
 		case codes.NotFound:
-			c.c.Log.WithError(err).WithField(telemetry.FederatedBundle, b).Warn("Federated bundle not found")
+			c.addErrorFields(err).WithField(telemetry.FederatedBundle, b).Warn("Federated bundle not found")


Related to my suggestion below, if we check for err == nil in this new method, we can call it once above this switch block, rather than for each error log in the switch cases.

It would be called once for each one of the federatedBundles that are being processed and use the logger that that method returns in each one of the cases, right?

Right, if you declare the local logger with the error fields before the switch block within the for loop, it will only use that logger for the federated bundle currently being examined.

Fixed at 55c88fa

rturner3 · 2023-07-03T18:37:31Z

pkg/agent/client/client_test.go

@@ -241,6 +243,12 @@ func TestRenewSVID(t *testing.T) {
 			agentErr: errors.New("renew fails"),
 			err:      "failed to renew agent: renew fails",
 		},
+		{
+			name:     "call to RenewAgent fails",


Can we also test that there is an error level log with the expected error fields?

Can be done separately to address #4474.

rturner3 · 2023-07-03T18:40:52Z

pkg/agent/client/client_test.go

@@ -344,6 +352,90 @@ func TestNewX509SVIDs(t *testing.T) {
 	assertConnectionIsNotNil(t, client)
 }

+func TestNewX509SVIDsFails(t *testing.T) {


Most of the code in this test is the same as in TestNewX509SVIDs. Can we re-use the existing setup logic in TestNewX509SVIDs and refactor it to be a table-driven test with this new test case?

Done at 5818be9

rturner3 · 2023-07-03T18:41:12Z

pkg/agent/client/client_test.go

+		},
+	}
+
+	tc.svidClient.batchSVIDErr = status.Error(codes.NotFound, "not found when executing BatchNewX509SVID")


Can we also test that there is an error level log with the expected error fields?

rturner3 · 2023-07-03T18:53:51Z

pkg/agent/client/client_test.go

+					ExpiresAt: issuedAt,
+					IssuedAt:  expiresAt,


These fields look mixed up, is it intentional?

Thanks. I forgot to change it after copying the previous test. Fixed at 7488427

rturner3 · 2023-07-03T18:54:27Z

pkg/agent/client/client_test.go

@@ -696,6 +824,19 @@ func TestFetchJWTSVID(t *testing.T) {
 			},
 			err: "JWTSVID issued after it has expired",
 		},
+		{
+			name: "grpc call to NewJWTSVID fails",


Can we also test that there is an error level log with the expected error fields?

MarcosDY · 2023-07-06T14:02:17Z

pkg/agent/client/client.go

+	logger := c.c.Log.WithError(err)
+	if s, ok := status.FromError(err); ok {
+		logger = c.c.Log.WithFields(logrus.Fields{


logger variable is not used to add fields, and setted with a new one, so WithError is missed,
you must use logger.WithFields instead

Fixed at 7b9fc68

rturner3 · 2023-07-12T20:02:14Z

Hey @Neniel, I see there's some commits from main that somehow got pulled into the branch supporting this PR. It looks like they were interleaved between the changes you're making, maybe there was a rebase that got messed up at some point?

In any case, the branch history for this PR can be cleaned up to just the changes you're proposing by running git rebase -i locally in your branch, and marking each commit unrelated to this PR as drop. Once the branch history includes only your commits on top of the main branch, doing a git push -f <remote> <branch> should clean things up here.

Also just as a suggestion for the future, running git merge main in the development branch is usually the best way to keep your development branch in sync with the latest. Additionally, doing a "force push" of development branches using git push -f makes it a bit harder for us as reviewers to see what has changed since the last time you pushed changes to the PR. Generally git push without -f is recommended (which is possible if you use git merge rather than git rebase to keep your development branch in sync).

… for grpc errors on spire agent Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

Co-authored-by: Ryan Turner <rturner3@users.noreply.github.com> Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

rturner3 · 2023-08-31T18:42:24Z

pkg/agent/client/client_test.go

+		{
+			name:           "success",
+			entries:        entries,
+			x509SVIDs:      x509SVIDs,


nit: since this is the same value in every subtest, we can remove x509SVIDs as a test template field

rturner3 · 2023-08-31T21:20:06Z

pkg/agent/client/client_test.go

+	assert.Error(t, err)
+	assertConnectionIsNil(t, client)
+
+	expectedLog := log.WithFields(


Ideally we would check that a log message was emitted that contained these fields rather than just checking if the logger had the fields added to it. We have methods like AssertLogs() in test/spiretest for this purpose. Since this kind of test coverage was not present in this package already, I'm ok if we defer this to a follow-up issue.

I've created #4474 to track the follow-up work.

rturner3 · 2023-08-31T21:20:25Z

pkg/agent/client/client_test.go

@@ -241,6 +243,12 @@ func TestRenewSVID(t *testing.T) {
 			agentErr: errors.New("renew fails"),
 			err:      "failed to renew agent: renew fails",
 		},
+		{
+			name:     "call to RenewAgent fails",


Can be done separately to address #4474.

…agent

Neniel force-pushed the structured-logging-for-grpc-errors-on-spire-agent branch from 9ca9bb6 to 4faa1fb Compare June 15, 2023 12:15

evan2645 assigned rturner3 Jun 15, 2023

rturner3 reviewed Jun 15, 2023

View reviewed changes

pkg/agent/client/client.go Outdated Show resolved Hide resolved

pkg/agent/client/client.go Show resolved Hide resolved

Neniel force-pushed the structured-logging-for-grpc-errors-on-spire-agent branch from 46a417f to 1bba9e2 Compare June 16, 2023 12:13

Neniel marked this pull request as ready for review June 16, 2023 12:14

Neniel requested review from evan2645, amartinezfayo, azdagron and MarcosDY as code owners June 16, 2023 12:14

MarcosDY reviewed Jun 16, 2023

View reviewed changes

Neniel force-pushed the structured-logging-for-grpc-errors-on-spire-agent branch 2 times, most recently from 3f2d9e7 to 22ac0cb Compare June 19, 2023 14:21

rturner3 reviewed Jun 22, 2023

View reviewed changes

Neniel force-pushed the structured-logging-for-grpc-errors-on-spire-agent branch from d07053b to f305c2a Compare June 27, 2023 13:56

rturner3 reviewed Jul 3, 2023

View reviewed changes

Neniel force-pushed the structured-logging-for-grpc-errors-on-spire-agent branch from 55c88fa to d049445 Compare July 4, 2023 10:35

MarcosDY reviewed Jul 6, 2023

View reviewed changes

Neniel force-pushed the structured-logging-for-grpc-errors-on-spire-agent branch from c4c0f36 to a712258 Compare July 10, 2023 13:30

Neniel force-pushed the structured-logging-for-grpc-errors-on-spire-agent branch 3 times, most recently from 2dbcc2f to b21fbce Compare July 21, 2023 16:04

Neniel force-pushed the structured-logging-for-grpc-errors-on-spire-agent branch from b21fbce to 539d3c7 Compare July 24, 2023 13:36

Neniel force-pushed the structured-logging-for-grpc-errors-on-spire-agent branch 2 times, most recently from 50123cc to 3d466f7 Compare August 24, 2023 18:33

Neniel added 5 commits August 24, 2023 15:34

implement structured logging for grpc errors on spire agented logging…

7129268

… for grpc errors on spire agent Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

reduce branching when handling grpc errors

d1cfb7a

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

add helper function

74ae833

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

add gRPC fields if applicable and the error

2da3732

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

add unit tests

b870c4d

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

Neniel and others added 10 commits August 24, 2023 15:34

goimport file

a92fed7

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

add tests for uncovered cases

ef11605

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

Update pkg/agent/client/client.go

f524f17

Co-authored-by: Ryan Turner <rturner3@users.noreply.github.com> Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

update new tests

6806c8b

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

call withErrorFields once in fetchBundles

aeac9f5

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

use table driven test

02e8ac7

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

fix expires at and issued at dates

a090c43

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

use logger variable

f47f264

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

fix lint issue

498ff60

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

sort imports

407362a

Signed-off-by: Neniel <11655196+Neniel@users.noreply.github.com>

Neniel force-pushed the structured-logging-for-grpc-errors-on-spire-agent branch from 3d466f7 to 407362a Compare August 24, 2023 18:35

rturner3 approved these changes Aug 31, 2023

View reviewed changes

Merge branch 'main' into structured-logging-for-grpc-errors-on-spire-…

e5043f1

…agent

azdagron merged commit 0483126 into spiffe:main Sep 1, 2023
31 checks passed

MarcosDY added this to the 1.8.0 milestone Sep 5, 2023

rturner3 mentioned this pull request Sep 5, 2023

Improve unit testing in pkg/agent/client package #4474

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement structured logging for gRPC errors on SPIRE agent #4262

Implement structured logging for gRPC errors on SPIRE agent #4262

Neniel commented Jun 15, 2023

rturner3 left a comment

MarcosDY Jun 16, 2023

Neniel Jun 16, 2023

MarcosDY Jun 16, 2023 •

edited

Loading

Neniel Jun 16, 2023

Neniel Jun 16, 2023

rturner3 Jun 22, 2023

Neniel Jun 27, 2023

Neniel Jun 27, 2023

Neniel Jun 30, 2023

rturner3 Jun 22, 2023

Neniel Jun 30, 2023

rturner3 Jul 3, 2023

Neniel Jul 4, 2023

rturner3 Jul 3, 2023

rturner3 Aug 31, 2023

rturner3 Jul 3, 2023

Neniel Jul 10, 2023

rturner3 Jul 3, 2023

rturner3 Jul 3, 2023

Neniel Jul 10, 2023

rturner3 Jul 3, 2023

MarcosDY Jul 6, 2023

Neniel Jul 10, 2023

rturner3 commented Jul 12, 2023

rturner3 Aug 31, 2023

rturner3 Aug 31, 2023

rturner3 Aug 31, 2023

Implement structured logging for gRPC errors on SPIRE agent #4262

Implement structured logging for gRPC errors on SPIRE agent #4262

Conversation

Neniel commented Jun 15, 2023

rturner3 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MarcosDY Jun 16, 2023 • edited Loading

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

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

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rturner3 commented Jul 12, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MarcosDY Jun 16, 2023 •

edited

Loading