Adding Trace IDs to log lines #624

shulin-sq · 2024-04-24T02:33:47Z

What type of PR is this?

Which issue does this PR fix:
#603

What does this PR do / Why do we need it:

If an issue # is not available please add repro steps and logs from aws-gateway-controller showing the issue:

Testing done on this change:

running in a development environment:

{"level":"info","ts":"2024-04-24T02:23:58.515Z","logger":"controller.route","caller":"controllers/route_controller.go:157","msg":"reconcile starting","type":"route","name":"lattice-redacted-srv-http","trace_id":"bc67d345-3b33-499a-9e3e-329e4dff92b9"}
{"level":"info","ts":"2024-04-24T02:23:58.515Z","logger":"controller.route","caller":"controllers/route_controller.go:277","msg":"Found aws-vpc-lattice for Route for lattice-redacted-srv-http, redacted-srv","trace_id":"bc67d345-3b33-499a-9e3e-329e4dff92b9"}
{"level":"info","ts":"2024-04-24T02:23:58.515Z","logger":"controller.route","caller":"controllers/route_controller.go:323","msg":"reconcile, adding or updating","name":"lattice-redacted-srv-http","trace_id":"bc67d345-3b33-499a-9e3e-329e4dff92b9"}
{"level":"info","ts":"2024-04-24T02:23:58.524Z","logger":"controller.iam-auth-policy","caller":"controllers/iamauthpolicy_controller.go:85","msg":"reconcile starting","type":"iamauthpolicy","name":"lattice-redacted-srv-http","trace_id":"ccdf0c8a-6fd0-43d6-86d4-5e4840e4a28c"}
{"level":"info","ts":"2024-04-24T02:23:58.524Z","logger":"controller.iam-auth-policy","caller":"controllers/iamauthpolicy_controller.go:96","msg":"reconcile IAM policy","req":"redacted-srv/lattice-redacted-srv-http","targetRef":{"group":"gateway.networking.k8s.io","kind":"HTTPRoute","name":"lattice-redacted-srv-http"},"tra
ce_id":"ccdf0c8a-6fd0-43d6-86d4-5e4840e4a28c"}
{"level":"info","ts":"2024-04-24T02:23:58.525Z","logger":"controller.route","caller":"gateway/model_build_lattice_service.go:122","msg":"Setting customer-domain-name: redacted-srv.global.dev.sq.lattice for route lattice-redacted-srv-http-redacted-srv","trace_id":"bc67d345-3b33-499a-9e3e-329e4dff92b9"}
{"level":"info","ts":"2024-04-24T02:24:11.292Z","logger":"controller.iam-auth-policy","caller":"controllers/iamauthpolicy_controller.go:114","msg":"reconciled IAM policy","req":"redacted-srv/lattice-redacted-srv-http","targetRef":{"group":"gateway.networking.k8s.io","kind":"HTTPRoute","name":"lattice-redacted-srv-http"},"i
sDeleted":false,"trace_id":"ccdf0c8a-6fd0-43d6-86d4-5e4840e4a28c"}
{"level":"info","ts":"2024-04-24T02:24:11.292Z","logger":"controller.iam-auth-policy","caller":"controllers/iamauthpolicy_controller.go:87","msg":"reconcile completed","name":"lattice-redacted-srv-http","type":"iamauthpolicy","trace_id":"ccdf0c8a-6fd0-43d6-86d4-5e4840e4a28c"}

Automation added to e2e:

Will this PR introduce any new dependencies?:

Will this break upgrades or downgrades. Has updating a running cluster been tested?:

Does this PR introduce any user-facing change?:

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

shulin-sq · 2024-04-24T02:36:13Z

pkg/controllers/accesslogpolicy_controller.go

+	ctx = gwlog.NewTrace(ctx)
+	gwlog.AddMetadata(ctx, "type", "accesslogpolicy")
+	gwlog.AddMetadata(ctx, "name", req.Name)
+
+	r.log.Infow(ctx, "reconcile starting", gwlog.GetMetadata(ctx)...)
+	defer func() {
+		r.log.Infow(ctx, "reconcile completed", gwlog.GetMetadata(ctx)...)
+	}()


here's an example of how I attempted to implement somehting like https://stripe.com/blog/canonical-log-lines

at the end of the reconcile event we can print out all the metadata saved in the context so far. eg this can include information like if issues occurred during the reconcile attempt that were ignorable, or decisions made while servicing the event.

I can see this being super useful.

shulin-sq · 2024-04-24T02:36:42Z

pkg/controllers/accesslogpolicy_controller.go

@@ -265,12 +273,12 @@ func (r *accessLogPolicyReconciler) buildAndDeployModel(
 	if err != nil {
 		return nil, err
 	}
-	r.log.Debugw("Successfully built model", "stack", jsonStack)
+	r.log.Debugw(context.TODO(), "Successfully built model", "stack", jsonStack)


for log lines that currently do not have a context in the scope, I added a todo for now

shulin-sq · 2024-04-24T02:37:28Z

pkg/controllers/eventhandlers/gateway.go

@@ -38,7 +38,7 @@ var ZeroTransitionTime = metav1.NewTime(time.Time{})
 func (h *enqueueRequestsForGatewayEvent) Create(ctx context.Context, e event.CreateEvent, queue workqueue.RateLimitingInterface) {
 	gwNew := e.Object.(*gateway_api.Gateway)

-	h.log.Infof("Received Create event for Gateway %s-%s", gwNew.Name, gwNew.Namespace)
+	h.log.Infof(ctx, "Received Create event for Gateway %s-%s", gwNew.Name, gwNew.Namespace)


these can also be effectively todo's. tracing starts in the controller. I made this decision since I couldn't figure out how to push the context into the reconcile queue

I think the only way we could maybe do that is by creating our own implementation of a NamespacedName that also includes the origin trace ID (generated here). Then we could push that object into the queue, cast it, and pull it out during Reconcile. We'd probably want to create a new trace ID for each reconcile operation anyway. Probably not something we need to solve right now.

shulin-sq · 2024-04-24T02:37:57Z

pkg/utils/gwlog/gwlog.go

 	"log"
 	"os"

 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )

-type Logger = *zap.SugaredLogger
+type TracedLogger struct {


here is where most of the changes are

shulin-sq · 2024-04-24T02:38:29Z

pkg/utils/gwlog/metadata.go

@@ -0,0 +1,65 @@
+package gwlog


this file is how I add the metadata fields into the context

erikfuller

Thanks for putting this together. It's nicely encapsulated and easy to understand, which takes the pressure off getting it perfect round one.

I don't have any major concerns with the approach, just added a couple comments/questions.

erikfuller · 2024-04-25T20:47:30Z

pkg/utils/gwlog/metadata.go

+
+func NewTrace(ctx context.Context) context.Context {
+	currID := uuid.New()
+	return context.WithValue(context.WithValue(ctx, traceID, currID.String()), metadata, newMetadata())


Looks like we'd have to recurse one level each time we wanted to get to the trace ID. Would it be more performant to have a struct with the metadata + the traceID? Alternatively, should the traceID just be part of the metadata? Or is there maybe some other benefit to nesting them like this I'm not seeing?

erikfuller · 2024-04-25T21:11:14Z

pkg/controllers/eventhandlers/gateway.go

@@ -38,7 +38,7 @@ var ZeroTransitionTime = metav1.NewTime(time.Time{})
 func (h *enqueueRequestsForGatewayEvent) Create(ctx context.Context, e event.CreateEvent, queue workqueue.RateLimitingInterface) {
 	gwNew := e.Object.(*gateway_api.Gateway)

-	h.log.Infof("Received Create event for Gateway %s-%s", gwNew.Name, gwNew.Namespace)
+	h.log.Infof(ctx, "Received Create event for Gateway %s-%s", gwNew.Name, gwNew.Namespace)


I think the only way we could maybe do that is by creating our own implementation of a NamespacedName that also includes the origin trace ID (generated here). Then we could push that object into the queue, cast it, and pull it out during Reconcile. We'd probably want to create a new trace ID for each reconcile operation anyway. Probably not something we need to solve right now.

erikfuller · 2024-04-25T21:12:05Z

pkg/controllers/accesslogpolicy_controller.go

+	ctx = gwlog.NewTrace(ctx)
+	gwlog.AddMetadata(ctx, "type", "accesslogpolicy")
+	gwlog.AddMetadata(ctx, "name", req.Name)
+
+	r.log.Infow(ctx, "reconcile starting", gwlog.GetMetadata(ctx)...)
+	defer func() {
+		r.log.Infow(ctx, "reconcile completed", gwlog.GetMetadata(ctx)...)
+	}()


I can see this being super useful.

shulin-sq added 4 commits April 22, 2024 15:06

run tests before building binary

da4ec88

logging library

8f60845

controller wrappers

87e3a0e

ignore pod reconcils

6a80c8c

shulin-sq commented Apr 24, 2024

View reviewed changes

erikfuller reviewed Apr 25, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adding Trace IDs to log lines #624

Adding Trace IDs to log lines #624

shulin-sq commented Apr 24, 2024 •

edited

shulin-sq Apr 24, 2024

erikfuller Apr 25, 2024

shulin-sq Apr 24, 2024

shulin-sq Apr 24, 2024

erikfuller Apr 25, 2024

shulin-sq Apr 24, 2024

shulin-sq Apr 24, 2024

erikfuller left a comment

erikfuller Apr 25, 2024

erikfuller Apr 25, 2024

erikfuller Apr 25, 2024

Adding Trace IDs to log lines #624

Are you sure you want to change the base?

Adding Trace IDs to log lines #624

Conversation

shulin-sq commented Apr 24, 2024 • 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

Choose a reason for hiding this comment

erikfuller left a 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

shulin-sq commented Apr 24, 2024 •

edited