feat(router): template expressions for access logs #1545

SkArchon · 2025-01-29T18:11:12Z

Motivation and Context

The goal is to extend the router to allow defining custom access log attributes by template expressions.

In order to do this the PR adds an "expression" field which can be set to process any log messages based on these exprlang expressions

However on top of this, the PR also goes ahead and adds the request error to the expressionContext.

This means that the user could now use expressions for access logs

access_logs:
  enabled: true
  router:
    fields:
    - key: "testthere"
      value_from:
        expression: "request.error ?? request.header.Get('X-WG-TRACE')"
  subgraphs:
    enabled: true
    fields:
      - key: "my-header"
        value_from:
          expression: "request.header.Get('X-WG-TRACE') == 'true' ? 'aa1' : 'aa2'"

In Progress / Remaining Work atm
Adding more of an "integration test" (right now I've written a unit test) for testing the expressions
docs

Checklist

I have discussed my proposed changes in an issue and have received approval to proceed.
I have followed the coding standards of the project.
Tests or benchmarks have been added or updated.
Documentation has been updated on https://github.com/wundergraph/cosmo-docs.
I have read the Contributors Guide.

Squashed commits: [1823f4836] fix: refactor logging and fix exprlang dereferencing [87ca8d1] Added template logging

SkArchon · 2025-01-29T19:24:52Z

A note on adding request.body The initial example given to me was

request.error ?? request.body

However, it seems like the body is not part of the expression context, when I was looking at adding it to the context I noticed it was of type io.Reader (readerCloser exact IIRC), which means that if the body was already read it is likely to be empty (of we will empty it by reading the io.Reader) + we would need to write code (I am assuming here) to output this to the log also.

As such, because of this + because the core specification was about adding the "error" to the context and allowing template expressions, I did not focus on this, and would like to discuss this more before continuing on deciding to add body.

SkArchon · 2025-01-29T19:26:06Z

router/core/request_context_fields.go

+	// and as the method receivers are all pointers (*reportError)
+	// the Error() function wont get called unless its of type *reportError
+	switch result := val.(type) {
+	case reportError:


As the comment mentions, depending on the expression exprlang will return reportError instead of the pointer version *reportError, which means that Error() wont end up being called

I can't follow. reportError is an internal error from our router and has nothing to do with expr. Could you eloborate?

Let's say the expression in the yml is expression: "request.error"

exprlang will evaluate the expression to *core.reportError

Which works

However if we do the expression expression: "request.error ?? request.url", exprlang will evaluate the expression to core.reportError (not a pointer)

The problem is that because the method uses a pointer receiver

func (e *reportError) Error() string {

the second expression does not call Error, thus will print out a memory address instead. Thus I cast it to *core.reportError

This could happen to any other similar errors (could happen both ways, depending on if the receiver is a pointer or not), however I only noticed this happening with core.reportError for now

Now I understand. You were referring to the returned error of the expression. Why do you believe it is important toi align this. The value should not matter because we will pass it straight to the logger which accepts any.

Even though the logger accepts any, the final log message ends up becoming a memory location. This becomes a problem when a customer expects the error message to be printed.

I'd expect that whatever the user returns in an expression that zap is able to log it and that the pointer is dereferenced automatically before printing.

From my testing so far no, but let me double check a bit more and get back to you.

SkArchon · 2025-01-29T19:30:36Z

router/internal/requestlogger/access_log_expression.go

@@ -0,0 +1,32 @@
+package requestlogger


The other function that tests the logger lies in this package requestlogger, but creating of the requestContext which is needed for evaluating expressions is in the core package, and is not exported.

Which means if I was to write my test cases the same way here in the subgraph_logger_test.go file, I will need to export the buildRequestContext function (and related struct), which seemed like a bad idea for this one test.

But it also made me wonder if that code should be in a separate (maybe "inner-core" package, or this package merged with core since its quite small?). I ended up writing a unit test directly access_log_field_handler_test in the core package.

…essions

router/pkg/config/config.schema.json

StarpTech · 2025-01-29T20:16:16Z

router/core/request_context_fields.go

+	// and as the method receivers are all pointers (*reportError)
+	// the Error() function wont get called unless its of type *reportError
+	switch result := val.(type) {
+	case reportError:


I can't follow. reportError is an internal error from our router and has nothing to do with expr. Could you eloborate?

router/core/access_log_field_handler_test.go

StarpTech · 2025-01-29T20:25:26Z

router/core/graphql_prehandler.go

@@ -217,7 +217,7 @@ func (h *PreHandler) Handler(next http.Handler) http.Handler {

 		executionOptions, traceOptions, err := h.parseRequestOptions(r, clientInfo, requestLogger)
 		if err != nil {
-			requestContext.error = err
+			AssignErrors(requestContext, err)


Instead of writing a utility function to assign the error, you could implement ResolveAnyExpression similar as withResolveStringExpression on the requestContext. This would follow the pattern and the error can be set right before we pass the expressionContext to the template engine.

Agree on the ResolveAnyExpression, however I want to clarify about assigning errors in the ResolveAnyExpression function.

My assumption was that whenever an error occurred that the error should be available as part of the expressionContext. So if anyone did
reqContext.expressionContext.errror at any time they wont get null (and would be the same requestContext.error).

With this change they would get null, which could be a mental model mismatch,

But from what you are saying is that they should not access the expressionContext this way so its ok, instead they should access it via any Resolve*Expression method, for which we will set the error to the expressionContext before the resolving step?

Correct. Thanks for the explanation.

router/internal/requestlogger/access_log_expression.go

StarpTech · 2025-01-29T20:44:53Z

 note on adding request.body The initial example given to me was

request.error ?? request.body

That's correct. I'd suggest to finish it up to the point we discussed it. We can add this later. The customer wanted to log the GraphQL operation in case of an error.

…gn to a pointer

SkArchon · 2025-01-30T18:40:42Z

router/core/context.go

 func (c *requestContext) ResolveStringExpression(expression *vm.Program) (string, error) {
+	c.setErrorContext()


We now set the expressionContext error when accessing through these functions

router/core/context.go

StarpTech · 2025-01-30T18:43:04Z

router/core/context.go

+	currContextRequest := c.expressionContext.Request
+	if err != nil {
+		// We don't really want to do a deep clone since we only know that error only can get modified
+		copyContext := expr.Context{


Why do we need to create a new expr.Context ? it's not clear from your comment.

SkArchon · 2025-01-30T18:44:30Z

router/core/context.go

+	currContextRequest := c.expressionContext.Request
+	if err != nil {
+		// We don't really want to do a deep clone since we only know that error only can get modified
+		copyContext := expr.Context{


I ran into a problem where when an error occurs in the subgraph, it's not assigned to the requestContext.error at the point of being called.

Thus any expressions like request.error?? 'no-error' returned 'no-error'. Observing the same pattern that was used in the predefined context fields for request_error which passes an error directly, I used a similar approach / workaround. Creating a copy of the expressionContext (non deep) and assigning it to resolve the expression.

SkArchon · 2025-01-30T18:46:54Z

router/core/errors.go

@@ -316,3 +316,14 @@ func writeOperationError(r *http.Request, w http.ResponseWriter, requestLogger *
 		writeRequestErrors(r, w, http.StatusInternalServerError, graphqlerrors.RequestErrorsFromError(errInternalServer), requestLogger)
 	}
 }
+
+type ExprWrapError struct {


This is to circumvent this problem described here:
#1545 (comment)

While testing further I noticed that there can be other error types, so it was safer to wrap the error in a type we can control, so we have a deterministic error type outputted from the exprlang expression.

(I didn't come across anything atm, but if there is a better existing type to use, we can reuse that)

SkArchon · 2025-01-30T18:47:36Z

router/core/context.go

+	if c.error == nil {
+		return
+	}
+	c.expressionContext.Request.Error = &ExprWrapError{c.error}


Refer https://github.com/wundergraph/cosmo/pull/1545/files#r1936122019 and #1545 (comment) for why we wrap

SkArchon · 2025-01-30T18:48:56Z

router/core/request_context_fields.go

+	logger *zap.Logger,
+	attributes []config.CustomAttribute,
+	exprAttributes []requestlogger.ExpressionAttribute,
+	passedErr error,


The previous type was "any" because it took inputs from panics and errors, I went ahead and split it into two as we want to maintain the error type in the ExpressionContext, but if we are ok to make it even more generic just for the panic, we can merge the fields again.

SkArchon · 2025-01-30T18:54:56Z

router/internal/requestlogger/access_log_expression.go

+			continue
+		}
+
+		err := exprlocal.ValidateAnyExpression(exprString)


Validate against nil and a few other types, we can add / remove types later as necessary

SkArchon added 5 commits January 29, 2025 23:38

feat: update schema with new expression field

1d8a7cb

chore: cleanup excess committed changes (+2 squashed commits)

e2e9dbd

Squashed commits: [1823f4836] fix: refactor logging and fix exprlang dereferencing [87ca8d1] Added template logging

chore: add to config full json

e6be8de

feat: adding tests

ee06984

chore: reset config urls

80c5d5e

github-actions bot added the router label Jan 29, 2025

SkArchon changed the title ~~feat(router): [WIP] template expressions for access logs~~ feat(router): template expressions for access logs Jan 29, 2025

chore: cleanup import changes

fcef449

SkArchon commented Jan 29, 2025

View reviewed changes

Merge branch 'main' into milindadias/access-logging-using-custom-expr…

2c9df23

…essions

SkArchon marked this pull request as ready for review January 29, 2025 19:51

SkArchon marked this pull request as draft January 29, 2025 19:54

chore: config message updates

059a45e

StarpTech requested changes Jan 29, 2025

View reviewed changes

SkArchon added 8 commits January 31, 2025 00:09

fix: cleanup expressions from main attribute slice

8b1d7c3

fix: update schema description

8578431

chore: added expr validation and added resolveAnyExpr

d4af84d

test: added tests

82fabd0

fix: resolve access logs in the subgraph

982d040

fix: use wrapper error so we have a determinstic error type to reassi…

d57815f

…gn to a pointer

test: add subgraph test

d418966

fix: broken tests

c6b6df6

SkArchon force-pushed the milindadias/access-logging-using-custom-expressions branch from b0e8ed0 to c6b6df6 Compare January 30, 2025 18:39

SkArchon commented Jan 30, 2025

View reviewed changes

StarpTech requested changes Jan 30, 2025

View reviewed changes

SkArchon commented Jan 30, 2025

View reviewed changes

SkArchon requested a review from StarpTech January 30, 2025 18:50

SkArchon commented Jan 30, 2025

View reviewed changes

SkArchon added 3 commits January 31, 2025 01:21

refactor: refactor error setter

b150cfb

chore: refactor test

37dd5ea

refactoring: fix the given review comments

801d07b

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(router): template expressions for access logs #1545

feat(router): template expressions for access logs #1545

SkArchon commented Jan 29, 2025 •

edited

Loading

SkArchon commented Jan 29, 2025 •

edited

Loading

SkArchon Jan 29, 2025

StarpTech Jan 29, 2025

SkArchon Jan 30, 2025

StarpTech Jan 30, 2025

SkArchon Jan 30, 2025

StarpTech Jan 30, 2025

SkArchon Jan 30, 2025

SkArchon Jan 29, 2025

StarpTech Jan 29, 2025

StarpTech Jan 29, 2025

SkArchon Jan 30, 2025 •

edited

Loading

StarpTech Jan 30, 2025

StarpTech commented Jan 29, 2025

SkArchon Jan 30, 2025

StarpTech Jan 30, 2025 •

edited

Loading

SkArchon Jan 30, 2025

SkArchon Jan 30, 2025

SkArchon Jan 30, 2025

SkArchon Jan 30, 2025

SkArchon Jan 30, 2025

		func (c requestContext) ResolveStringExpression(expression vm.Program) (string, error) {
		c.setErrorContext()

feat(router): template expressions for access logs #1545

Are you sure you want to change the base?

feat(router): template expressions for access logs #1545

Conversation

SkArchon commented Jan 29, 2025 • edited Loading

Motivation and Context

Checklist

SkArchon commented Jan 29, 2025 • 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

SkArchon Jan 30, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

StarpTech commented Jan 29, 2025

Choose a reason for hiding this comment

StarpTech Jan 30, 2025 • 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

SkArchon commented Jan 29, 2025 •

edited

Loading

SkArchon commented Jan 29, 2025 •

edited

Loading

SkArchon Jan 30, 2025 •

edited

Loading

StarpTech Jan 30, 2025 •

edited

Loading