fix: add failing webhook async dispatch test

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)

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
+		}
+	}
+}