fix(#254): deal with timeouts caused by sending email taking too long

internal/service/attendeesrv/adminsrv.go

@@ -43,7 +43,7 @@ func (s *AttendeeServiceImplData) UpdateAdminInfo(ctx context.Context, attendee
 
 	// setting admin flags such as guest may change dues, and change status
 	subject := ctxvalues.Subject(ctx)
-	err = s.UpdateDuesAndDoStatusChangeIfNeeded(ctx, attendee, currentStatus, currentStatus, fmt.Sprintf("admin info update by %s", subject), overrideDuesTransactionComment, suppressMinorUpdateEmail)
+	err = s.UpdateDuesAndDoStatusChangeIfNeeded(ctx, attendee, currentStatus, currentStatus, fmt.Sprintf("admin info update by %s", subject), overrideDuesTransactionComment, suppressMinorUpdateEmail, false)
 	if err != nil {
 		return err
 	}

internal/service/attendeesrv/attendeesrv.go

@@ -101,7 +101,7 @@ func (s *AttendeeServiceImplData) UpdateAttendee(ctx context.Context, attendee *
 
 	subject := ctxvalues.Subject(ctx)
 	// changing packages may change the due amount
-	err = s.UpdateDuesAndDoStatusChangeIfNeeded(ctx, attendee, currentStatus, currentStatus, fmt.Sprintf("attendee update by %s", subject), "", suppressMinorUpdateEmails)
+	err = s.UpdateDuesAndDoStatusChangeIfNeeded(ctx, attendee, currentStatus, currentStatus, fmt.Sprintf("attendee update by %s", subject), "", suppressMinorUpdateEmails, false)
 	if err != nil {
 		return err
 	}

internal/service/attendeesrv/interfaces.go

@@ -39,7 +39,11 @@ type AttendeeService interface {
 	// If newStatus is one of approved/partially paid/paid, the actual status value written may be any of these three.
 	// This is because depending on package and flag changes (guests attend for free!), the dues may change, and
 	// so paid may turn into partially paid etc.
-	UpdateDuesAndDoStatusChangeIfNeeded(ctx context.Context, attendee *entity.Attendee, oldStatus status.Status, newStatus status.Status, statusComment string, overrideDuesComment string, suppressMinorUpdateEmail bool) error
+	//
+	// Since sending emails sometimes takes a long time, causing the payments webhook to time out, emails can
+	// be sent asynchronously, but this is not recommended during normal operations as this can cause emails to pile up
+	// in the mail service.
+	UpdateDuesAndDoStatusChangeIfNeeded(ctx context.Context, attendee *entity.Attendee, oldStatus status.Status, newStatus status.Status, statusComment string, overrideDuesComment string, suppressMinorUpdateEmail bool, asyncEmail bool) error
 	StatusChangeAllowed(ctx context.Context, attendee *entity.Attendee, oldStatus status.Status, newStatus status.Status) error
 	StatusChangePossible(ctx context.Context, attendee *entity.Attendee, oldStatus status.Status, newStatus status.Status) error
 	// ResendStatusMail resends the current status mail, but with dues recalculated

internal/service/attendeesrv/status.go

@@ -47,7 +47,7 @@ func (s *AttendeeServiceImplData) GetFullStatusHistory(ctx context.Context, atte
 	return result, nil
 }
 
-func (s *AttendeeServiceImplData) UpdateDuesAndDoStatusChangeIfNeeded(ctx context.Context, attendee *entity.Attendee, oldStatus status.Status, newStatus status.Status, statusComment string, overrideDuesComment string, suppressMinorUpdateEmail bool) error {
+func (s *AttendeeServiceImplData) UpdateDuesAndDoStatusChangeIfNeeded(ctx context.Context, attendee *entity.Attendee, oldStatus status.Status, newStatus status.Status, statusComment string, overrideDuesComment string, suppressMinorUpdateEmail bool, asyncEmail bool) error {
 	// controller checks value validity
 	// controller checks permission via StatusChangeAllowed
 	// controller checks precondition via StatusChangePossible
@@ -89,13 +89,13 @@ func (s *AttendeeServiceImplData) UpdateDuesAndDoStatusChangeIfNeeded(ctx contex
 
 		if newStatus != status.Deleted && newStatus != status.CheckedIn {
 			suppress := suppressMinorUpdateEmail && isPaymentPhaseStatus(oldStatus) && isPaymentPhaseStatus(newStatus)
-			err = s.sendStatusChangeNotificationEmail(ctx, attendee, adminInfo, newStatus, statusComment, suppress)
+			err = s.sendStatusChangeNotificationEmail(ctx, attendee, adminInfo, newStatus, statusComment, suppress, asyncEmail)
 			if err != nil {
 				return err
 			}
 		}
 	} else if duesInformationChanged && (newStatus == status.Approved || newStatus == status.PartiallyPaid) {
-		err = s.sendStatusChangeNotificationEmail(ctx, attendee, adminInfo, newStatus, statusComment, suppressMinorUpdateEmail)
+		err = s.sendStatusChangeNotificationEmail(ctx, attendee, adminInfo, newStatus, statusComment, suppressMinorUpdateEmail, asyncEmail)
 		if err != nil {
 			return err
 		}
@@ -129,7 +129,7 @@ func (s *AttendeeServiceImplData) ResendStatusMail(ctx context.Context, attendee
 	}
 
 	if currentStatus != status.Deleted && currentStatus != status.CheckedIn && currentStatus != status.New {
-		err = s.sendStatusChangeNotificationEmail(ctx, attendee, adminInfo, currentStatus, currentStatusComment, false)
+		err = s.sendStatusChangeNotificationEmail(ctx, attendee, adminInfo, currentStatus, currentStatusComment, false, false)
 		if err != nil {
 			return err
 		}
@@ -138,7 +138,7 @@ func (s *AttendeeServiceImplData) ResendStatusMail(ctx context.Context, attendee
 	return nil
 }
 
-func (s *AttendeeServiceImplData) sendStatusChangeNotificationEmail(ctx context.Context, attendee *entity.Attendee, adminInfo *entity.AdminInfo, newStatus status.Status, statusComment string, suppress bool) error {
+func (s *AttendeeServiceImplData) sendStatusChangeNotificationEmail(ctx context.Context, attendee *entity.Attendee, adminInfo *entity.AdminInfo, newStatus status.Status, statusComment string, suppress bool, asyncSend bool) error {
 	checkSummedId := s.badgeId(attendee.ID)
 	cancelReason := ""
 	if newStatus == status.Cancelled {
@@ -191,9 +191,25 @@ func (s *AttendeeServiceImplData) sendStatusChangeNotificationEmail(ctx context.
 		return nil
 	}
 
-	err := mailservice.Get().SendEmail(ctx, mailDto)
-	if err != nil {
-		return err
+	if asyncSend {
+		asyncCtx := ctxvalues.AsyncContextFrom(ctx)
+		asyncCtx, cancel := context.WithTimeout(asyncCtx, 30*time.Second)
+		go func() {
+			defer cancel()
+			aulogging.Logger.Ctx(asyncCtx).Info().Printf("asynchronously sending mail %s", mailDto.CommonID)
+
+			err := mailservice.Get().SendEmail(asyncCtx, mailDto)
+			if err != nil {
+				aulogging.Logger.Ctx(asyncCtx).Warn().Printf("failed to send asynchronous mail %s to %s - cannot fail original request: %s", mailDto.CommonID, attendee.Email, err.Error())
+				return
+			}
+			aulogging.Logger.Ctx(asyncCtx).Info().Printf("success sending mail %s to %s", mailDto.CommonID, attendee.Email)
+		}()
+	} else {
+		err := mailservice.Get().SendEmail(ctx, mailDto)
+		if err != nil {
+			return err
+		}
 	}
 	return nil
 }

internal/web/controller/attendeectl/config_test.go

@@ -89,7 +89,7 @@ func (s *MockAttendeeService) GetFullStatusHistory(ctx context.Context, attendee
 	return []entity.StatusChange{}, nil
 }
 
-func (s *MockAttendeeService) UpdateDuesAndDoStatusChangeIfNeeded(ctx context.Context, attendee *entity.Attendee, oldStatus status.Status, newStatus status.Status, statusComment string, overrideDuesComment string, suppressMinorUpdateEmail bool) error {
+func (s *MockAttendeeService) UpdateDuesAndDoStatusChangeIfNeeded(ctx context.Context, attendee *entity.Attendee, oldStatus status.Status, newStatus status.Status, statusComment string, overrideDuesComment string, suppressMinorUpdateEmail bool, asyncEmail bool) error {
 	return nil
 }
 

internal/web/controller/statusctl/statusctl.go

@@ -29,7 +29,7 @@ func Create(server chi.Router, attendeeSrv attendeesrv.AttendeeService) {
 	attendeeService = attendeeSrv
 
 	server.Get("/api/rest/v1/attendees/{id}/status", filter.LoggedInOrApiToken(filter.WithTimeout(3*time.Second, getStatusHandler)))
-	server.Post("/api/rest/v1/attendees/{id}/status", filter.LoggedInOrApiToken(filter.WithTimeout(3*time.Second, postStatusHandler)))
+	server.Post("/api/rest/v1/attendees/{id}/status", filter.LoggedInOrApiToken(filter.WithTimeout(10*time.Second, postStatusHandler)))
 	server.Get("/api/rest/v1/attendees/{id}/status-history", filter.HasGroupOrApiToken(config.OidcAdminGroup(), filter.WithTimeout(3*time.Second, getStatusHistoryHandler)))
 	server.Post("/api/rest/v1/attendees/{id}/status/resend", filter.HasGroupOrApiToken(config.OidcAdminGroup(), filter.WithTimeout(10*time.Second, resendStatusMailHandler)))
 	server.Post("/api/rest/v1/attendees/{id}/payments-changed", filter.HasGroupOrApiToken(config.OidcAdminGroup(), filter.WithTimeout(10*time.Second, paymentsChangedHandler)))
@@ -97,7 +97,7 @@ func postStatusHandler(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	err = attendeeService.UpdateDuesAndDoStatusChangeIfNeeded(ctx, att, latestStatusChange.Status, dto.Status, dto.Comment, "", false)
+	err = attendeeService.UpdateDuesAndDoStatusChangeIfNeeded(ctx, att, latestStatusChange.Status, dto.Status, dto.Comment, "", false, false)
 	if err != nil {
 		if errors.Is(err, paymentservice.DownstreamError) || errors.Is(err, mailservice.DownstreamError) {
 			statusChangeDownstreamError(ctx, w, r, err)
@@ -189,7 +189,7 @@ func paymentsChangedHandler(w http.ResponseWriter, r *http.Request) {
 	err = attendeeService.UpdateDuesAndDoStatusChangeIfNeeded(ctx, att,
 		latestStatusChange.Status,
 		latestStatusChange.Status,
-		"transactions changed", "", false)
+		"transactions changed", "", false, true)
 	if err != nil {
 		if errors.Is(err, paymentservice.DownstreamError) || errors.Is(err, mailservice.DownstreamError) {
 			statusChangeDownstreamError(ctx, w, r, err)

internal/web/util/ctxvalues/accessors.go

@@ -28,6 +28,25 @@ func CreateContextWithValueMap(ctx context.Context) context.Context {
 	return ctx
 }
 
+// AsyncContextFrom takes a request context and returns a disassociated
+// asynchronous context, but with all the values intact. The values are copied to the new context.
+//
+// Use for async processing. Allows originalCtx to be cancelled or time out
+// without affecting the context returned.
+func AsyncContextFrom(origCtx context.Context) context.Context {
+	newContextMap := make(map[string]string)
+
+	origContextMapUntyped := origCtx.Value(ContextMap)
+	if origContextMapUntyped != nil {
+		origContextMap := origContextMapUntyped.(map[string]string)
+		for k, v := range origContextMap {
+			newContextMap[k] = v
+		}
+	}
+
+	return context.WithValue(context.Background(), ContextMap, newContextMap)
+}
+
 func valueOrDefault(ctx context.Context, key string, defaultValue string) string {
 	contextMapUntyped := ctx.Value(ContextMap)
 	if contextMapUntyped == nil {

internal/web/util/ctxvalues/accessors_test.go

@@ -18,3 +18,13 @@ func TestRetrieveRequestId(t *testing.T) {
 	SetRequestId(ctx, "hallo")
 	require.Equal(t, "hallo", RequestId(ctx), "unexpected value retrieving request id that was just set")
 }
+
+func TestAsyncContextFrom(t *testing.T) {
+	docs.Description("if present, the context values should carry over to an async context, but later changes should not")
+	ctx := CreateContextWithValueMap(context.TODO())
+	SetRequestId(ctx, "hallo")
+
+	asyncCtx := AsyncContextFrom(ctx)
+	SetRequestId(ctx, "changed")
+	require.Equal(t, "hallo", RequestId(asyncCtx), "unexpected value retrieving request id")
+}