Request ID Logging #1087

NickMeves · 2021-03-08T04:54:42Z

Supports logging of a client's X-Request-ID

Description

Track a RequestID throughout the lifespan of a request in the RequestScope. If a X-Request-Id is set in the client request headers, we use that. Otherwise we make a random UUID.

The RequestID is used in auth & request logging, Error pages & added to upstream HTTP requests (if it wasn't originally present & we generated our own UUID).

Motivation and Context

Increase logging and tracing of requests throughout the application to ease debugging.

How Has This Been Tested?

Unit Tests

Checklist:

My change requires a change to the documentation or CHANGELOG.
I have updated the documentation/CHANGELOG accordingly.
I have created a feature (non-master) branch for my PR.

NickMeves · 2021-03-08T05:03:03Z

When we use our request builder for requests to provider endpoints, should we inject the X-Request-Id header with our Context/RequestScope RequestID?

If yes -- we can probably make it automatic if a context were added?

(This PR does add it to HTTP requests to the upstream where it didn't already exist and we made our own random UUID, that is up for discussion too).

pkg/app/pagewriter/error.html

pkg/logger/logger.go

NickMeves · 2021-03-13T01:40:02Z

When we use our request builder for requests to provider endpoints, should we inject the X-Request-Id header with our Context/RequestScope RequestID?

If yes -- we can probably make it automatic if a context were added?

(This PR does add it to HTTP requests to the upstream where it didn't already exist and we made our own random UUID, that is up for discussion too).

Let's not do this for now. I've also removed injecting request ID into upstream headers for the time being.

This is better handled with a future tracing PR.

docs/docs/configuration/overview.md

pkg/apis/middleware/scope.go

pkg/apis/options/logging.go

pkg/app/pagewriter/error.html

pkg/app/pagewriter/error_page.go

JoelSpeed · 2021-03-13T08:20:24Z

pkg/middleware/scope_test.go

 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
 )

+const requestID = "11111111-2222-4333-8444-555555555555"


Same as before, can we rename?

Suggested change

const requestID = "11111111-2222-4333-8444-555555555555"

const testRequestID = "11111111-2222-4333-8444-555555555555"

JoelSpeed · 2021-03-13T08:20:54Z

pkg/middleware/scope_test.go

@@ -48,6 +52,11 @@ var _ = Describe("Scope Suite", func() {
 				Expect(scope).ToNot(BeNil())
 				Expect(scope.ReverseProxy).To(BeFalse())
 			})
+
+			It("sets the RequestID using the request", func() {


Do we have a test when the request ID isn't already set?

Added tests for no + custom request ID headers

JoelSpeed · 2021-03-13T08:21:42Z

pkg/requests/util/util.go

+	XForwardedProto = "X-Forwarded-Proto"
+	XForwardedHost  = "X-Forwarded-Host"
+	XForwardedURI   = "X-Forwarded-Uri"
+	XRequestID      = "X-Request-Id"


Oh I see why this is here now, I'm a bit conflicted. Do we import the other consts into other packages?

I'm trying to remember why in this package I had util_test as a separate package when I made this suite for the other header helpers 🤔

I think that's the main reason I made these public, let me play around with getting the test suite to share a package and get these private.

Maybe my thinking was since this is request utils these are useful constants other packages could use to match up with our getters? I dunno, now I'm rationalizing for a past version of myself I don't remember 🤣

Oh - I left a comment for myself why:

// TestRequestUtilSuite and related tests are in a *_test package // to prevent circular imports with the `logger` package which uses // this functionality func TestRequestUtilSuite(t *testing.T) {

Leave it public? Or make private and duplicate in the util_test package?

Happy to leave it public, will likely come in useful somewhere else anyways

JoelSpeed · 2021-03-13T08:24:31Z

pkg/requests/util/util.go

+	XRequestID      = "X-Request-Id"
+)
+
+var requestIDHeader = XRequestID


Does this get overriden when the config is loaded? Not a huge fan of this 🤔

How many times is this actually used in the code? I see it's used in tests a lot but this should actually only be in the scope middleware right? Maybe logging? Perhaps we want to pass in the configured value every time?

I guess this is kind of like how things are done in the logger package right, configuring the default logger? Perhaps lets add a comment explaining why this is done this way and leave it?

So GetRequestID is a little overloaded 😅

func GetRequestID(req *http.Request) string { scope := middlewareapi.GetRequestScope(req) if scope != nil { return scope.RequestID } rid := req.Header.Get(requestIDHeader) if rid != "" { return rid } return uuid.New().String() }

The first time it is called for a request, it is in the Scope initialization itself, so it falls through to the 2nd or 3rd case and sets the scope (only time our configured requestIDHeader is used). Every other time in the lifecycle, scope is set so it is pulling from that first block.

I guess we are technically memoizing on the middlewareapi.Scope for how we consume it in practice.

Should we separate this out, so we have two different things.

In the request scope middleware, we add or generate the request ID.

We have a helper here to read it from the scope

This way we can pass the request ID header as a parameter when we construct the middleware scope, will likely be cleaner than the current implementation right?

Question for you since you are more familiar with the ordering of everything:

Since GetRequestID is used in logging/error pages, I opted to merge the two cases (rather than GetRequestID always assuming a scope was already initialized) in case we had a scenario where we errored or attemtped to log before the scope was initialied.

That's the benefit of keeping aligned. But Is that a thing? Otherwise you are right, could be split to be cleaner.

The scope middleware should be the first thing in the request chain, so, unless we do any logging that would use the request ID as part of the middleware scope, then we are safe

JoelSpeed · 2021-03-13T08:28:55Z

pkg/requests/util/util_test.go

+			})
+
+			AfterEach(func() {
+				util.SetRequestIDHeader(util.XRequestID)


The unset logic is to have an empty value right? This should do the same? (This would then look similar to below and allow us to change the default under the hood)

Suggested change

util.SetRequestIDHeader(util.XRequestID)

util.SetRequestIDHeader("")

Though I see you have explicit tests below so maybe this can be ignored

JoelSpeed · 2021-03-15T12:44:53Z

pkg/middleware/scope.go

@@ -13,7 +13,7 @@ func NewScope(reverseProxy bool) alice.Constructor {
 		return http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
 			scope := &middlewareapi.RequestScope{
 				ReverseProxy: reverseProxy,
-				RequestID:    requestutil.GetRequestID(req),
+				RequestID:    requestutil.GenRequestID(req),


I had intended for the generation logic to be in this package, that way the request ID header that is configured doesn't need to be set anywhere as a package level var. Everything else can rely just on the request scope

So I'm torn for 2 reasons:

1.) The actual business logic really matches everything else that is happening in requestutils.
2.) If the requestutils.GetRequestID we consume throughout the application is truly only RequestScope aware, in tests we'd need to setup a full scope setting middleware in all their setup. At the moment it's easy to just splice in the extra header for non-middleware related test suites.

The original intent was to memoize the random UUID case, and I guess things got wonky because we jumped across boundaries to RequestScope to perform the semi-memoization (since it was the first caller setting it on itself). In a RequestScope free world, I would memoize this in the GetRequestID on its own Context key.

Do we want to do that? Or maybe still memoize in the RequestScope, but not set it on RequestScope initialization, but instead actually memoize (set the stored value on the first real call to it)?

Ah - I follow, the concern is mostly around the management of the custom request ID header -- missed that aspect in the previous discussion 🤔

This way we can pass the request ID header as a parameter when we construct the middleware scope, will likely be cleaner than the current implementation right?

Eh - just realized concern (2) isn't that big of a deal, we have this at our fingertips to setup tests without the full middleware handler: req = middlewareapi.AddRequestScope(req, scope)

We have created a pattern where we add the request scope in all our tests anyway, so ensuring this always gets created with request ID at the beginning as well shouldn't add too much extra bloat right?

Yeah, I think it isn't too bad. I was initially thinking of the handler route where we spun up the whole middleware for all handler related tests. Our non-middleware test suites didn't have that easy injection point. But I can use req = middlewareapi.AddRequestScope(req, scope) super easily 👍

I think my plan of attack is to completely remove request ID logic from requestutils and have the logic be owned by RequestScope

Alrighty - Moved everything over to RequestScope management in the last commit and ditched the package variables & requestutils management of the ID.

pkg/app/pagewriter/error_page.go

JoelSpeed · 2021-03-20T23:42:53Z

pkg/app/pagewriter/pagewriter.go

+// HTML sanitization policy creation done once for lifespan of the program
+var sanitizer = bluemonday.StrictPolicy()


Hmm yes that's a good point, we should definitely be sanitizing anything we log, maybe leave that for a future PR as you've suggested though

pkg/app/pagewriter/sign_in_page_test.go

JoelSpeed · 2021-03-20T23:45:33Z

pkg/requests/util/util.go

+	XForwardedProto = "X-Forwarded-Proto"
+	XForwardedHost  = "X-Forwarded-Host"
+	XForwardedURI   = "X-Forwarded-Uri"
+	XRequestID      = "X-Request-Id"


Happy to leave it public, will likely come in useful somewhere else anyways

JoelSpeed

Very nearly there, I think the only real thing for me is that sanitzer vs html escape question

pkg/app/pagewriter/error_page.go

JoelSpeed · 2021-03-21T11:18:26Z

pkg/app/pagewriter/error_page_test.go


 			body, err := ioutil.ReadAll(recorder.Result().Body)
 			Expect(err).ToNot(HaveOccurred())
-			Expect(string(body)).To(Equal("Forbidden An extra message: with more context. /prefix/ 403 /redirect Custom Footer Text v0.0.0-test"))
+			Expect(string(body)).To(Equal("Forbidden You do not have permission to access this resource. /prefix/ 403 /redirect  Custom Footer Text v0.0.0-test"))


HTML escape would probably be easier to understand wouldn't it? Then you at least see that there was something there rather than an empty string? Thinking from a UX perspective here

pkg/middleware/scope.go

NickMeves · 2021-03-21T17:21:16Z

Apparently we got HTML escaping out of the box 😄

I left in a test case to assert that we indeed still escaping in the future.

JoelSpeed

LGTM, thanks @NickMeves

* Add RequestID to the RequestScope * Expose RequestID to auth & request loggers * Use the RequestID in templated HTML pages * Allow customizing the RequestID header * Document new Request ID support * Add more cases to scope/requestID tests * Split Get vs Generate RequestID funtionality * Add {{.RequestID}} to the request logger tests * Move RequestID management to RequestScope * Use HTML escape instead of sanitization for Request ID rendering

NickMeves requested a review from JoelSpeed March 8, 2021 04:55

NickMeves force-pushed the request-id-logging branch from ebae484 to d27e983 Compare March 8, 2021 04:56

NickMeves linked an issue Mar 8, 2021 that may be closed by this pull request

Support X-Request-ID in Access Logs #965

Closed

NickMeves force-pushed the request-id-logging branch 2 times, most recently from 72b1e76 to 0229e18 Compare March 8, 2021 05:16

NickMeves commented Mar 8, 2021

View reviewed changes

pkg/app/pagewriter/error.html Show resolved Hide resolved

JoelSpeed added this to In Progress (Pull Requests) in Release v7.1.0 via automation Mar 11, 2021

NickMeves commented Mar 11, 2021

View reviewed changes

pkg/logger/logger.go Outdated Show resolved Hide resolved

NickMeves force-pushed the request-id-logging branch 4 times, most recently from aaf1870 to e96c232 Compare March 13, 2021 01:38

NickMeves marked this pull request as ready for review March 13, 2021 01:40

NickMeves requested a review from a team as a code owner March 13, 2021 01:40

NickMeves added the enhancement label Mar 13, 2021

NickMeves force-pushed the request-id-logging branch from e96c232 to 776de4e Compare March 13, 2021 01:49

JoelSpeed reviewed Mar 13, 2021

View reviewed changes

Nick Meves added 6 commits March 14, 2021 09:49

Add RequestID to the RequestScope

172f542

Expose RequestID to auth & request loggers

2e02cdc

Use the RequestID in templated HTML pages

44a50ac

Allow customizing the RequestID header

af2df49

Document new Request ID support

ef8a413

Add more cases to scope/requestID tests

e9be27c

NickMeves force-pushed the request-id-logging branch from 776de4e to e9be27c Compare March 14, 2021 16:50

Split Get vs Generate RequestID funtionality

94adc10

JoelSpeed reviewed Mar 15, 2021

View reviewed changes

Add {{.RequestID}} to the request logger tests

44080a8

JoelSpeed reviewed Mar 20, 2021

View reviewed changes

NickMeves force-pushed the request-id-logging branch from 32a1a9b to 6b17dc0 Compare March 21, 2021 02:24

JoelSpeed reviewed Mar 21, 2021

View reviewed changes

Move RequestID management to RequestScope

f73c2e0

NickMeves force-pushed the request-id-logging branch from 6b17dc0 to f73c2e0 Compare March 21, 2021 16:54

Use HTML escape instead of sanitization for Request ID rendering

24335fc

JoelSpeed approved these changes Mar 21, 2021

View reviewed changes

JoelSpeed merged commit c1267bb into master Mar 21, 2021

Release v7.1.0 automation moved this from In Progress (Pull Requests) to Done Mar 21, 2021

JoelSpeed deleted the request-id-logging branch March 21, 2021 18:27

JoelSpeed mentioned this pull request Nov 17, 2021

Include Request details in error logs #1324

Closed

ShivanKKP mentioned this pull request Oct 31, 2022

Injecting request ID into upstream headers #1871

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Request ID Logging #1087

Request ID Logging #1087

NickMeves commented Mar 8, 2021 •

edited

NickMeves commented Mar 8, 2021

NickMeves commented Mar 13, 2021

JoelSpeed Mar 13, 2021

JoelSpeed Mar 13, 2021

NickMeves Mar 13, 2021

JoelSpeed Mar 13, 2021

NickMeves Mar 13, 2021

NickMeves Mar 13, 2021 •

edited

NickMeves Mar 13, 2021

NickMeves Mar 13, 2021

JoelSpeed Mar 20, 2021

JoelSpeed Mar 13, 2021

NickMeves Mar 13, 2021

JoelSpeed Mar 14, 2021

NickMeves Mar 14, 2021

JoelSpeed Mar 14, 2021

JoelSpeed Mar 13, 2021

JoelSpeed Mar 15, 2021

NickMeves Mar 15, 2021

NickMeves Mar 15, 2021

NickMeves Mar 15, 2021 •

edited

JoelSpeed Mar 15, 2021

NickMeves Mar 15, 2021

NickMeves Mar 21, 2021

JoelSpeed Mar 20, 2021

JoelSpeed Mar 20, 2021

JoelSpeed left a comment

JoelSpeed Mar 21, 2021

NickMeves commented Mar 21, 2021

JoelSpeed left a comment

	const requestID = "11111111-2222-4333-8444-555555555555"
	const testRequestID = "11111111-2222-4333-8444-555555555555"

	util.SetRequestIDHeader(util.XRequestID)
	util.SetRequestIDHeader("")

		// HTML sanitization policy creation done once for lifespan of the program
		var sanitizer = bluemonday.StrictPolicy()

Request ID Logging #1087

Request ID Logging #1087

Conversation

NickMeves commented Mar 8, 2021 • edited

Description

Motivation and Context

How Has This Been Tested?

Checklist:

NickMeves commented Mar 8, 2021

NickMeves commented Mar 13, 2021

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

NickMeves Mar 13, 2021 • 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

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

NickMeves Mar 15, 2021 • 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

JoelSpeed left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

NickMeves commented Mar 21, 2021

JoelSpeed left a comment

Choose a reason for hiding this comment

NickMeves commented Mar 8, 2021 •

edited

NickMeves Mar 13, 2021 •

edited

NickMeves Mar 15, 2021 •

edited