diff --git a/selfservice/hook/web_hook.go b/selfservice/hook/web_hook.go index 98bc24fc27c3..b798f9e39914 100644 --- a/selfservice/hook/web_hook.go +++ b/selfservice/hook/web_hook.go @@ -8,6 +8,7 @@ import ( "encoding/json" "fmt" "net/http" + "time" "github.com/pkg/errors" "github.com/tidwall/gjson" @@ -282,6 +283,8 @@ func (e *WebHook) execute(ctx context.Context, data *templateContext) error { } errChan := make(chan error, 1) + e.deps.Logger().WithRequest(req.Request).Info("Dispatching webhook") + t0 := time.Now() go func() { defer close(errChan) @@ -307,9 +310,16 @@ func (e *WebHook) execute(ctx context.Context, data *templateContext) error { }() if gjson.GetBytes(e.conf, "response.ignore").Bool() { + traceID, spanID := span.SpanContext().TraceID(), span.SpanContext().SpanID() go func() { - err := <-errChan - e.deps.Logger().WithError(err).Warning("A web hook request failed but the error was ignored because the configuration indicated that the upstream response should be ignored.") + if err := <-errChan; err != nil { + e.deps.Logger().WithField("otel", map[string]string{ + "trace_id": traceID.String(), + "span_id": spanID.String(), + }).WithError(err).Warning("Webhook request failed but the error was ignored because the configuration indicated that the upstream response should be ignored.") + } else { + e.deps.Logger().WithField("duration", time.Since(t0)).Info("Webhook request succeeded") + } }() return nil } @@ -323,7 +333,7 @@ func parseWebhookResponse(resp *http.Response) (err error) { } var hookResponse rawHookResponse if err := json.NewDecoder(resp.Body).Decode(&hookResponse); err != nil { - return errors.Wrap(err, "hook response could not be unmarshalled properly from JSON") + return errors.Wrap(err, "webhook response could not be unmarshalled properly from JSON") } var validationErrs []*schema.ValidationError @@ -343,11 +353,11 @@ func parseWebhookResponse(resp *http.Response) (err error) { Context: detail.Context, }) } - validationErrs = append(validationErrs, schema.NewHookValidationError(msg.InstancePtr, "a web-hook target returned an error", messages)) + validationErrs = append(validationErrs, schema.NewHookValidationError(msg.InstancePtr, "a webhook target returned an error", messages)) } if len(validationErrs) == 0 { - return errors.New("error while parsing hook response: got no validation errors") + return errors.New("error while parsing webhook response: got no validation errors") } return schema.NewValidationListError(validationErrs) diff --git a/selfservice/hook/web_hook_integration_test.go b/selfservice/hook/web_hook_integration_test.go index 1c7ddb21df00..bef9bef44680 100644 --- a/selfservice/hook/web_hook_integration_test.go +++ b/selfservice/hook/web_hook_integration_test.go @@ -19,6 +19,7 @@ import ( "testing" "time" + "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/require" "github.com/ory/kratos/schema" @@ -365,7 +366,7 @@ func TestWebHooks(t *testing.T) { }`, ) - webhookError := schema.NewValidationListError([]*schema.ValidationError{schema.NewHookValidationError("#/traits/username", "a web-hook target returned an error", text.Messages{{ID: 1234, Type: "info", Text: "error message"}})}) + webhookError := schema.NewValidationListError([]*schema.ValidationError{schema.NewHookValidationError("#/traits/username", "a webhook target returned an error", text.Messages{{ID: 1234, Type: "info", Text: "error message"}})}) for _, tc := range []struct { uc string callWebHook func(wh *hook.WebHook, req *http.Request, f flow.Flow, s *session.Session) error @@ -839,3 +840,97 @@ func TestDisallowPrivateIPRanges(t *testing.T) { require.Contains(t, err.Error(), "192.168.178.0 is not a public IP address") }) } + +func TestAsyncWebhook(t *testing.T) { + conf, reg := internal.NewFastRegistryWithMocks(t) + _ = conf + // conf.MustSet(ctx, config.ViperKeyClientHTTPNoPrivateIPRanges, true) + // conf.MustSet(ctx, config.ViperKeyClientHTTPPrivateIPExceptionURLs, []string{webhookReceiver.URL}) + logger := logrusx.New("kratos", "test") + logHook := new(test.Hook) + logger.Logger.Hooks.Add(logHook) + whDeps := struct { + x.SimpleLoggerWithClient + *jsonnetsecure.TestProvider + }{ + x.SimpleLoggerWithClient{L: logger, C: reg.HTTPClient(context.Background()), T: otelx.NewNoop(logger, &otelx.Config{ServiceName: "kratos"})}, + jsonnetsecure.NewTestProvider(t), + } + + req := &http.Request{ + Header: map[string][]string{"Some-Header": {"Some-Value"}}, + Host: "www.ory.sh", + TLS: new(tls.ConnectionState), + URL: &url.URL{Path: "/some_end_point"}, + Method: http.MethodPost, + } + incomingCtx, incomingCancel := context.WithCancel(context.Background()) + if deadline, ok := t.Deadline(); ok { + var cleanup context.CancelFunc + incomingCtx, cleanup = context.WithDeadline(incomingCtx, deadline.Add(-time.Second)) + defer cleanup() + } + req = req.WithContext(incomingCtx) + s := &session.Session{ID: x.NewUUID(), Identity: &identity.Identity{ID: x.NewUUID()}} + f := &login.Flow{ID: x.NewUUID()} + + handlerEntered, blockHandlerOnExit := make(chan struct{}), make(chan struct{}) + webhookReceiver := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + close(handlerEntered) + <-blockHandlerOnExit + w.Write([]byte("ok")) + })) + t.Cleanup(webhookReceiver.Close) + // defer webhookReceiver.Close() + + wh := hook.NewWebHook(&whDeps, json.RawMessage(fmt.Sprintf(` + { + "url": %q, + "method": "GET", + "body": "file://stub/test_body.jsonnet", + "response": { + "ignore": true + } + }`, webhookReceiver.URL))) + err := wh.ExecuteLoginPostHook(nil, req, node.DefaultGroup, f, s) + require.NoError(t, err) // execution returns immediately for async webhook + select { + case <-time.After(200 * time.Millisecond): + t.Fatal("timed out waiting for webhook request to reach test handler") + case <-handlerEntered: + // ok + } + // 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 + testFor := time.After(200 * time.Millisecond) + for done := false; !done; { + if last := logHook.LastEntry(); last != nil { + msg, err := last.String() + require.NoError(t, err) + assert.Contains(t, msg, "Dispatching webhook") + } + + select { + case <-testFor: + done = true + case <-time.After(50 * time.Millisecond): + // continue loop + } + } + logHook.Reset() + close(blockHandlerOnExit) + testFor = time.After(200 * time.Millisecond) + for done := false; !done; { + if last := logHook.LastEntry(); last != nil { + msg, err := last.String() + require.NoError(t, err) + assert.Contains(t, msg, "Webhook request succeeded") + } + select { + case <-testFor: + done = true + case <-time.After(50 * time.Millisecond): + // continue loop + } + } +}