Create or renew or reauthorize subscription may need a lot of retries to succeed, due to "Subscription validation request timed out" #2805
Labels
status:waiting-for-triage
An issue that is yet to be reviewed or assigned
type:bug
A broken experience
Describe the bug
I have to use Polly to retry all subscription requests that need validation (Creation or Renewal or Reauthorize) because sometimes it works on first attempt, but sometimes I need 10 attempts (Retry policy is configured with an initial delay of 2s then exponential) !
My test service is deployed on IIS and is responding quickly to requests.
I have of course followed instructions detailed hereafter otherwise it would never work: https://learn.microsoft.com/en-us/graph/change-notifications-delivery-webhooks?tabs=csharp
I have also configured lifecycle notifications and can for exemple Reauthorize (but still with Polly retries).
When I'm getting the exception "Subscription validation request timed out", this is because the service simply does not receive the validation request from MS Graph!
Logs hereafter shows one example where I try to renew the subscription with a new ExpirationDateTime. 3rd attempt fails again because the validation request is simply not sent at all (no Request starting in logs), then the 4th attempt succeeds because the appropriate validation request was sent!
What could produce the need to have so many attempts ?!?
What could block the request?!?
// 3rd attempt
2025-01-23 12:38:42.6260|0|INFO |Greisch.Exchange.Graph.Services.MessageSubscriptionManager|Subscription 73cc32cb-6421-4e78-8aea-9a07d9dfb610 is valid until 01/23/2025 12:41:58 +01:00
2025-01-23 12:38:42.6260|0|INFO |Greisch.Exchange.Graph.Services.MessageSubscriptionManager|Renewing subscription 73cc32cb-6421-4e78-8aea-9a07d9dfb610 expiring 01/23/2025 12:41:58 +01:00
2025-01-23 12:38:52.7268|3|WARN |Polly|Execution attempt. Source: 'SubscriptionLifecyclePipeline/(null)/Retry', Operation Key: '', Result: 'Subscription validation request timed out.', Handled: 'True', Attempt: '3', Execution Time: 10100,9616ms Microsoft.Graph.Models.ODataErrors.ODataError: Subscription validation request timed out.
at Microsoft.Kiota.Http.HttpClientLibrary.HttpClientRequestAdapter.ThrowIfFailedResponseAsync(HttpResponseMessage response, Dictionary
2 errorMapping, Activity activityForAttributes, CancellationToken cancellationToken) at Microsoft.Kiota.Http.HttpClientLibrary.HttpClientRequestAdapter.SendAsync[ModelType](RequestInformation requestInfo, ParsableFactory
1 factory, Dictionary2 errorMapping, CancellationToken cancellationToken) at Microsoft.Kiota.Http.HttpClientLibrary.HttpClientRequestAdapter.SendAsync[ModelType](RequestInformation requestInfo, ParsableFactory
1 factory, Dictionary2 errorMapping, CancellationToken cancellationToken) at Microsoft.Graph.Subscriptions.Item.SubscriptionItemRequestBuilder.PatchAsync(Subscription body, Action
1 requestConfiguration, CancellationToken cancellationToken)at Greisch.Exchange.Graph.Services.MessageSubscriptionManager.RenewSubscriptionAsync() in D:\Source\Repos\gti5\Greisch.Exchange.Graph\Services\MessageSubscriptionManager.cs:line 111
at web_service_net.Services.MessageSubscriptionService.b__4_1(CancellationToken _) in D:\Source\Repos\gti5\web-service-net\web-service-net\Services\MessageSubscriptionService.cs:line 47
at Polly.ResiliencePipeline.<>c.<b__3_0>d.MoveNext()
2025-01-23 12:38:52.7573|0|WARN |Polly|Resilience event occurred. EventName: 'OnRetry', Source: 'SubscriptionLifecyclePipeline/(null)/Retry', Operation Key: '', Result: 'Subscription validation request timed out.' Microsoft.Graph.Models.ODataErrors.ODataError: Subscription validation request timed out.
at Microsoft.Kiota.Http.HttpClientLibrary.HttpClientRequestAdapter.ThrowIfFailedResponseAsync(HttpResponseMessage response, Dictionary
2 errorMapping, Activity activityForAttributes, CancellationToken cancellationToken) at Microsoft.Kiota.Http.HttpClientLibrary.HttpClientRequestAdapter.SendAsync[ModelType](RequestInformation requestInfo, ParsableFactory
1 factory, Dictionary2 errorMapping, CancellationToken cancellationToken) at Microsoft.Kiota.Http.HttpClientLibrary.HttpClientRequestAdapter.SendAsync[ModelType](RequestInformation requestInfo, ParsableFactory
1 factory, Dictionary2 errorMapping, CancellationToken cancellationToken) at Microsoft.Graph.Subscriptions.Item.SubscriptionItemRequestBuilder.PatchAsync(Subscription body, Action
1 requestConfiguration, CancellationToken cancellationToken)at Greisch.Exchange.Graph.Services.MessageSubscriptionManager.RenewSubscriptionAsync() in D:\Source\Repos\gti5\Greisch.Exchange.Graph\Services\MessageSubscriptionManager.cs:line 111
at web_service_net.Services.MessageSubscriptionService.b__4_1(CancellationToken _) in D:\Source\Repos\gti5\web-service-net\web-service-net\Services\MessageSubscriptionService.cs:line 47
at Polly.ResiliencePipeline.<>c.<b__3_0>d.MoveNext()
// 4th attempt
2025-01-23 12:39:08.7733|0|INFO |Greisch.Exchange.Graph.Services.MessageSubscriptionManager|Subscription 73cc32cb-6421-4e78-8aea-9a07d9dfb610 is valid until 01/23/2025 12:41:58 +01:00
2025-01-23 12:39:08.7733|0|INFO |Greisch.Exchange.Graph.Services.MessageSubscriptionManager|Renewing subscription 73cc32cb-6421-4e78-8aea-9a07d9dfb610 expiring 01/23/2025 12:41:58 +01:00
2025-01-23 12:39:08.9316|1|INFO |Microsoft.AspNetCore.Hosting.Diagnostics|Request starting HTTP/1.1 POST https://<our_server>:<port_number>/api/notifications?validationToken=Validation%3a+Testing+client+application+reachability+for+subscription+Request-Id%3a+0c120f47-5744-4b59-a9e4-75c0bcfc0b66 - text/plain;+charset=utf-8 0
(...)
2025-01-23 12:39:09.0806|0|INFO |web_service_net.Controllers.NotificationsController|NotificationsController: Validation: Testing client application reachability for subscription Request-Id: 0c120f47-5744-4b59-a9e4-75c0bcfc0b66
(...)
2025-01-23 12:39:09.0806|2|INFO |Microsoft.AspNetCore.Hosting.Diagnostics|Request finished HTTP/1.1 POST https://<our_server>:<port_number>/api/notifications?validationToken=Validation%3a+Testing+client+application+reachability+for+subscription+Request-Id%3a+0c120f47-5744-4b59-a9e4-75c0bcfc0b66 - 200 - text/plain;+charset=utf-8 156.2338ms
Expected behavior
Retry with Polly is a good practice but the need to retry should be exceptional.
I have to configure Polly to retry forever to ensure my requests succeed!
Validation request with validationToken should always be sent...
How to reproduce
Here's one part of my controller that is responsible to ensure endpoint can be validated:
[ApiController]
[AllowAnonymous]
[Produces("text/plain")]
public abstract class BaseNotificationsController(ILogger logger) : ControllerBase
{
[HttpPost]
public async Task ReceiveNotification([FromQuery] string? validationToken = null, [FromBody] NotificationCollection? notifications = null)
{
if (!string.IsNullOrEmpty(validationToken))
{
logger.LogInformation("{type}: {validationToken}", GetType().Name, validationToken);
return Ok(validationToken);
}
}
SDK Version
5.68.0
Latest version known to work for scenario above?
No response
Known Workarounds
Retry forever with Polly, but I may miss notifications if Renewal fails due to expired subscription that are automatically removed.
Debug output
Click to expand log
```The text was updated successfully, but these errors were encountered: