fix: spurious cancelation of async webhooks, better tracing #2969

alnr · 2022-12-19T17:31:50Z

Previously, async webhooks (response.ignore=true) would be canceled early once the incoming Kratos request was served and it's associated context released. We now dissociate the cancellation of async hooks from the normal request processing flow.

I've also improved the OpenTelemetry instrumentation.

aeneasr

Can you please add a test that shows this change to be effective? You can probably add a test which executes a webhook where the target takes ~5 seconds to respond or something similar. Even better, if test without your patch fails

aeneasr · 2022-12-19T17:40:20Z

selfservice/hook/web_hook.go

+		errChan                          = make(chan error, 1)
+	)
+	if async {
+		ctx, cancel = context.WithTimeout(context.Background(), 5*time.Minute)


I don't think this would fix the issue, the underlying HTTP client may be canceling the request, not the context? It has a timeout of I think 10 seconds.

Using a background context is also a possible security issue. Please make sure that we're not confusing the context and name this, for example, asyncContext, and only use it in the correct execution branch

The problem is the context being passed to this function (execute) being canceled/released while the async webhook is still in flight.

How is a background context a security issue?

aeneasr · 2022-12-19T17:42:20Z

selfservice/hook/web_hook.go

+		ctx, cancel = context.WithTimeout(context.Background(), 5*time.Minute)
+		spanOpts = append(spanOpts, trace.WithNewRoot())
+	}
+	ctx, span := tracer.Start(ctx, "Webhook", spanOpts...)


Here for example is the first instance where the incorrect context is used if async is true. The trace would be lost and without context!

The code is correct. For async webhooks, we start a new root span which is not associated with the incoming span.

What do you think of doing something like this:

req := // ... var cancel // ... if (async) { makeRequestContext, cancel = context.WithTimeout(context.Background(), time.Minute()) req = req.WithContext(ctx) }

that way, we ensure that the context is never leaving the async execution path :)

The code is correct. For async webhooks, we start a new root span which is not associated with the incoming span.

But then the span would not appear as part of the request, and it would not be possible to correlate it to an incoming HTTP request? Is that really intentional?

Yes, the span would be orphaned in that sense. But still easy enough to find.

If you made the async webhook a child span of the incoming Kratos request span, the child will outlive the parent span. That will trip up many tools and generally violate OpenTelemetry semantics.

OpenTracing used to have a special trace-trace relationship (FollowsFrom) which was perfect for cases like this. AFAIK, that did not make it into the OpenTelemetry specification, though, and tooling support was sketchy.

Oh I see, that is a very good explanation - thank you!

So I did not include this in the merge, would you be open to make a follow-up PR with the span fixed?

The merged patch is fine as-is. The OpenTelemetry people themselves are not sure how they want to models this: open-telemetry/opentelemetry-specification#65

I'd suggest looking at some traces in Jaeger and Tempo, and deciding whether we're OK with how those tools interpret the data in practice. If there's a major hiccup, we can then change the instrumentation.

Perfect, that sounds like a plan!

alnr · 2022-12-19T18:18:01Z

Can you please add a test that shows this change to be effective? You can probably add a test which executes a webhook where the target takes ~5 seconds to respond or something similar. Even better, if test without your patch fails

Will add a test.

alnr · 2022-12-19T21:11:45Z

Added failing test as first commit and my fix as second.

Previously, async webhooks (response.ignore=true) would be canceled early once the incoming Kratos request was served and it's associated context released. We now dissociate the cancellation of async hooks from the normal request processing flow.

codecov · 2022-12-19T21:48:03Z

Codecov Report

Merging #2969 (1da1cd1) into master (e11ba52) will increase coverage by 0.08%.
The diff coverage is 95.12%.

@@            Coverage Diff             @@
##           master    #2969      +/-   ##
==========================================
+ Coverage   76.10%   76.18%   +0.08%     
==========================================
  Files         313      309       -4     
  Lines       19310    19071     -239     
==========================================
- Hits        14695    14529     -166     
+ Misses       3487     3416      -71     
+ Partials     1128     1126       -2

Impacted Files	Coverage Δ
selfservice/hook/web_hook.go	`81.56% <95.12%> (+1.66%)`	⬆️
credentialmigrate/migrate.go	`75.00% <0.00%> (-7.36%)`	⬇️
identity/handler.go	`87.95% <0.00%> (-2.33%)`	⬇️
selfservice/strategy/webauthn/nodes.go	`100.00% <0.00%> (ø)`
x/keys.go
identity/credentials_webauthn.go
selfservice/strategy/oidc/provider_lark.go
identity/credentials_lookup.go
selfservice/strategy/oidc/provider_config.go	`34.04% <0.00%> (+0.04%)`	⬆️

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

aeneasr · 2022-12-20T06:51:32Z

selfservice/hook/web_hook_integration_test.go

+	// at this point, a goroutine is in the middle of the call to our test handler and waiting for a response
+	incomingCancel() // simulate the incoming Kratos request having finished
+	timeout := time.After(200 * time.Millisecond)
+	for done := false; !done; {


handlerEntered should indicate that we already entered the HTTP webhook target. I think we don't need to also check the log entry

selfservice/hook/web_hook.go

aeneasr · 2022-12-20T07:15:42Z

selfservice/hook/web_hook.go

-		async                            = gjson.GetBytes(e.conf, "response.ignore").Bool()
-		parseResponse                    = gjson.GetBytes(e.conf, "can_interrupt").Bool()
-		tracer                           = trace.SpanFromContext(ctx).TracerProvider().Tracer("kratos-webhooks")
-		cancel        context.CancelFunc = func() {}


The cancel function was not needed IMO. We only used it to cancel the time out, but the underlying HTTP client already has a timeout itself (it's 30 seconds)

aeneasr · 2022-12-20T07:16:40Z

selfservice/hook/web_hook.go

+		// incoming request context is cancelled.
+		//
+		// The webhook will still cancel after 30 seconds as that is the configured timeout for the HTTP client.
+		req = req.WithContext(context.Background())


Instead of overshadowing the context, we now use context.Background() only where it is needed - in the request context. An alternative would be to not include a context if the request is async:

if !ignoreResponse { req = req.WithContext(ctx) }

aeneasr · 2022-12-20T07:17:18Z

selfservice/hook/web_hook.go

+		logger := e.deps.Logger().WithField("otel", map[string]string{
+			"trace_id": traceID.String(),
+			"span_id":  spanID.String(),
+		})


Always include trace info

aeneasr · 2022-12-20T07:18:18Z

selfservice/hook/web_hook_integration_test.go

 	timeout := time.After(200 * time.Millisecond)
-	for done := false; !done; {


I don't think this was needed, as we already wait for handlerEntered

aeneasr · 2022-12-20T07:19:24Z

selfservice/hook/web_hook_integration_test.go

+	var found bool
+	for !found {
+		for _, entry := range logHook.AllEntries() {
+			if entry.Message == "Webhook request succeeded" {


Make this independent of ordering and just look whether we find the succeeded log entry :)

Previously, async webhooks (response.ignore=true) would be canceled early once the incoming Kratos request was served and it's associated context released. We now dissociate the cancellation of async hooks from the normal request processing flow.

alnr requested review from aeneasr and zepatrik as code owners December 19, 2022 17:31

alnr self-assigned this Dec 19, 2022

aeneasr reviewed Dec 19, 2022

View reviewed changes

alnr force-pushed the fix-async-webhooks branch from 852ab26 to 33766f4 Compare December 19, 2022 21:09

alnr force-pushed the fix-async-webhooks branch from 33766f4 to 23de15f Compare December 19, 2022 21:16

alnr added 2 commits December 19, 2022 22:19

fix: add failing webhook async dispatch test

c2adc6b

alnr force-pushed the fix-async-webhooks branch from 23de15f to 134295e Compare December 19, 2022 21:19

aeneasr reviewed Dec 20, 2022

View reviewed changes

github-advanced-security bot found potential problems Dec 20, 2022

View reviewed changes

selfservice/hook/web_hook.go Fixed Show fixed Hide fixed

chore: code review

1da1cd1

aeneasr force-pushed the fix-async-webhooks branch from 8b54913 to 1da1cd1 Compare December 20, 2022 07:14

aeneasr reviewed Dec 20, 2022

View reviewed changes

aeneasr approved these changes Dec 20, 2022

View reviewed changes

aeneasr merged commit 72de640 into master Dec 20, 2022

aeneasr deleted the fix-async-webhooks branch December 20, 2022 08:21

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: spurious cancelation of async webhooks, better tracing #2969

fix: spurious cancelation of async webhooks, better tracing #2969

alnr commented Dec 19, 2022

aeneasr left a comment

aeneasr Dec 19, 2022

alnr Dec 19, 2022

aeneasr Dec 19, 2022

alnr Dec 19, 2022

aeneasr Dec 19, 2022

aeneasr Dec 19, 2022

alnr Dec 20, 2022

aeneasr Dec 20, 2022

alnr Dec 20, 2022

aeneasr Dec 20, 2022

alnr commented Dec 19, 2022

alnr commented Dec 19, 2022

codecov bot commented Dec 19, 2022 •

edited

Loading

aeneasr Dec 20, 2022

aeneasr Dec 20, 2022

aeneasr Dec 20, 2022

aeneasr Dec 20, 2022

aeneasr Dec 20, 2022

aeneasr Dec 20, 2022 •

edited

Loading

		timeout := time.After(200 * time.Millisecond)
		for done := false; !done; {

fix: spurious cancelation of async webhooks, better tracing #2969

fix: spurious cancelation of async webhooks, better tracing #2969

Conversation

alnr commented Dec 19, 2022

aeneasr 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

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

alnr commented Dec 19, 2022

alnr commented Dec 19, 2022

codecov bot commented Dec 19, 2022 • edited Loading

Codecov Report

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

aeneasr Dec 20, 2022 • edited Loading

Choose a reason for hiding this comment

codecov bot commented Dec 19, 2022 •

edited

Loading

aeneasr Dec 20, 2022 •

edited

Loading