[QUERY] Storage queue message visibility timer behavior change between track 1 and track 2 extensions

Library name and version

Microsoft.Azure.WebJobs.Extensions.Storage v4.0.5, v5.0.0

Query/Question

In both track 1 and track 2 extensions for storage triggers, there is an internal timer, CreateUpdateMessageVisibilityTimer, which updates the queue message's visibilityTimeout property after half the visibilityTimeout has elapsed, as long as the function is still running and healthy, which allows a function to execute on a message for an arbitrary amount of time, without the message becoming visible again in the queue and picked up by another instance. The timer is created here and executed here for track 2, and created here and executed here for track 1.

However, I see different behavior for this timer between the two tracks, when examining the NextVisibleTime/nextVisibleOn of the CloudQueueMessage/QueueMessage object. In track 1, I see the property changes, but I don't see such a change using track 2.

I have this simple queue trigger function to illustrate this behavior. Using track 1:

[FunctionName("QueueTrigger1")]
public async Task Run([QueueTrigger("test-queue", Connection = "connection")]CloudQueueMessage myQueueItem, ILogger log)
{
    for (var i = 0; i < 20; i++) {
        log.LogInformation($"Minute {i}: nextVisibleTime: {myQueueItem.NextVisibleTime}, popReceipt: {myQueueItem.PopReceipt}");
        await Task.Delay(60000);
    }
}

When triggered, I see the following output:

[2022-02-07T21:55:57.273Z] Executing 'QueueTrigger1' (Reason='New queue message detected on 'test-queue'.', Id=da32acb1-2154-4033-b38b-b3ce5b51ca5d)
[2022-02-07T21:55:57.280Z] Trigger Details: MessageId: 1617305c-f4e5-4479-bb86-a4c4692cd991, DequeueCount: 1, InsertionTime: 2022-02-07T21:55:56.000+00:00
[2022-02-07T21:55:57.325Z] Minute 0: nextVisibleTime: 2/7/2022 10:05:56 PM +00:00, popReceipt: AgAAAAMAAAAAAAAA+dpv4W4c2AE=
[2022-02-07T21:56:57.336Z] Minute 1: nextVisibleTime: 2/7/2022 10:05:56 PM +00:00, popReceipt: AgAAAAMAAAAAAAAA+dpv4W4c2AE=
[2022-02-07T21:57:57.345Z] Minute 2: nextVisibleTime: 2/7/2022 10:05:56 PM +00:00, popReceipt: AgAAAAMAAAAAAAAA+dpv4W4c2AE=
[2022-02-07T21:58:57.359Z] Minute 3: nextVisibleTime: 2/7/2022 10:05:56 PM +00:00, popReceipt: AgAAAAMAAAAAAAAA+dpv4W4c2AE=
[2022-02-07T21:59:57.379Z] Minute 4: nextVisibleTime: 2/7/2022 10:05:56 PM +00:00, popReceipt: AgAAAAMAAAAAAAAA+dpv4W4c2AE=
[2022-02-07T22:00:57.396Z] Minute 5: nextVisibleTime: 2/7/2022 10:10:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAlAddlG8c2AEBAAAA
[2022-02-07T22:01:57.412Z] Minute 6: nextVisibleTime: 2/7/2022 10:10:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAlAddlG8c2AEBAAAA
[2022-02-07T22:02:57.423Z] Minute 7: nextVisibleTime: 2/7/2022 10:10:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAlAddlG8c2AEBAAAA
[2022-02-07T22:03:57.450Z] Minute 8: nextVisibleTime: 2/7/2022 10:10:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAlAddlG8c2AEBAAAA
[2022-02-07T22:04:57.457Z] Minute 9: nextVisibleTime: 2/7/2022 10:10:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAlAddlG8c2AEBAAAA
[2022-02-07T22:05:57.464Z] Minute 10: nextVisibleTime: 2/7/2022 10:15:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAsjVBR3Ac2AEBAAAA
[2022-02-07T22:06:57.478Z] Minute 11: nextVisibleTime: 2/7/2022 10:15:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAsjVBR3Ac2AEBAAAA
[2022-02-07T22:07:57.517Z] Minute 12: nextVisibleTime: 2/7/2022 10:15:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAsjVBR3Ac2AEBAAAA
[2022-02-07T22:08:57.532Z] Minute 13: nextVisibleTime: 2/7/2022 10:15:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAsjVBR3Ac2AEBAAAA
[2022-02-07T22:09:57.543Z] Minute 14: nextVisibleTime: 2/7/2022 10:15:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAsjVBR3Ac2AEBAAAA
[2022-02-07T22:10:57.557Z] Minute 15: nextVisibleTime: 2/7/2022 10:20:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAWKUi+nAc2AEBAAAA
[2022-02-07T22:11:57.574Z] Minute 16: nextVisibleTime: 2/7/2022 10:20:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAWKUi+nAc2AEBAAAA
[2022-02-07T22:12:57.596Z] Minute 17: nextVisibleTime: 2/7/2022 10:20:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAWKUi+nAc2AEBAAAA
[2022-02-07T22:13:57.610Z] Minute 18: nextVisibleTime: 2/7/2022 10:20:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAWKUi+nAc2AEBAAAA
[2022-02-07T22:14:57.622Z] Minute 19: nextVisibleTime: 2/7/2022 10:20:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAWKUi+nAc2AEBAAAA
[2022-02-07T22:15:57.699Z] Executed 'QueueTrigger1' (Succeeded, Id=da32acb1-2154-4033-b38b-b3ce5b51ca5d, Duration=1200486ms)

I can see the NextVisibleTime property change over time. However, when using track 2:

[FunctionName("QueueTrigger1")]
public async Task Run([QueueTrigger("test-queue", Connection = "connection")]QueueMessage myQueueItem, ILogger log)
{
     for (var i = 0; i < 20; i++) {
         log.LogInformation($"Minute {i}: nextVisibleOn: {myQueueItem.NextVisibleOn}, popReceipt: {myQueueItem.PopReceipt}");
         await Task.Delay(60000);
     }
}

I see the following output:

[2022-02-07T23:57:19.232Z] Executing 'QueueTrigger1' (Reason='New queue message detected on 'test-queue'.', Id=6771e937-6079-41a1-827b-168ccbc2735b)
[2022-02-07T23:57:19.236Z] Trigger Details: MessageId: e8b713c8-e03d-4485-bb72-925b3bcaf6ee, DequeueCount: 1, InsertedOn: 2022-02-07T23:57:16.000+00:00
[2022-02-07T23:57:19.289Z] Minute 0: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-07T23:57:22.560Z] Host lock lease acquired by instance ID '0000000000000000000000009AB4A82A'.
[2022-02-07T23:58:19.314Z] Minute 1: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-07T23:59:19.328Z] Minute 2: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:00:19.351Z] Minute 3: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:01:19.367Z] Minute 4: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:02:19.390Z] Minute 5: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:03:19.398Z] Minute 6: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:04:19.445Z] Minute 7: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:05:19.460Z] Minute 8: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:06:19.487Z] Minute 9: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:07:19.508Z] Minute 10: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:08:19.516Z] Minute 11: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:09:19.538Z] Minute 12: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:10:19.555Z] Minute 13: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:11:19.574Z] Minute 14: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:12:19.585Z] Minute 15: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:13:19.606Z] Minute 16: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:14:19.613Z] Minute 17: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:15:19.637Z] Minute 18: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:16:19.659Z] Minute 19: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE=
[2022-02-08T00:17:19.811Z] Executed 'QueueTrigger1' (Succeeded, Id=6771e937-6079-41a1-827b-168ccbc2735b, Duration=1200700ms)

Sometimes it even causes the message to be visible and processed again, without any visible logs or warnings that updating the visibilityTimeout failed. For example:

[2022-02-07T22:51:26.365Z] Executing 'QueueTrigger1' (Reason='New queue message detected on 'test-queue'.', Id=8228ec1e-5a12-4d84-ba91-d919b01bcc74)
[2022-02-07T22:51:26.371Z] Trigger Details: MessageId: 3a4cefa2-a37b-4055-8489-34297171bde2, DequeueCount: 1, InsertedOn: 2022-02-07T22:51:24.000+00:00
[2022-02-07T22:51:26.406Z] Minute 0: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T22:52:26.422Z] Minute 1: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T22:53:26.448Z] Minute 2: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T22:54:26.477Z] Minute 3: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T22:55:26.495Z] Minute 4: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T22:56:26.518Z] Minute 5: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T22:57:26.549Z] Minute 6: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T22:58:26.563Z] Minute 7: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T22:58:47.672Z] Executing 'QueueTrigger1' (Reason='New queue message detected on 'test-queue'.', Id=ee791174-f0bc-402c-b202-01f4eabc911b)
[2022-02-07T22:58:47.674Z] Trigger Details: MessageId: 688a3631-b367-4748-8261-6a4de98cabac, DequeueCount: 2, InsertedOn: 2022-02-07T22:48:44.000+00:00
[2022-02-07T22:58:47.675Z] Minute 0: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE=
[2022-02-07T22:59:26.575Z] Minute 8: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T22:59:47.681Z] Minute 1: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE=
[2022-02-07T23:00:26.582Z] Minute 9: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T23:00:47.692Z] Minute 2: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE=
[2022-02-07T23:01:26.590Z] Minute 10: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T23:01:47.711Z] Minute 3: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE=
[2022-02-07T23:02:26.602Z] Minute 11: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T23:02:47.732Z] Minute 4: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE=
[2022-02-07T23:03:26.620Z] Minute 12: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T23:03:47.740Z] Minute 5: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE=
[2022-02-07T23:04:26.630Z] Minute 13: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T23:04:47.747Z] Minute 6: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE=
[2022-02-07T23:05:26.651Z] Minute 14: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T23:05:47.779Z] Minute 7: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE=
[2022-02-07T23:06:26.680Z] Minute 15: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=
[2022-02-07T23:06:47.785Z] Minute 8: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE=
[2022-02-07T23:07:26.693Z] Minute 16: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE=

In either case though, I don't see the nextVisibleOn property updating as time passes.

Is this change in behavior to be expected? Is it documented somewhere?

Environment

Windows 10.0.22000 .NET SDK v6.0.101

Label prediction was below confidence level 0.6 for Model:ServiceLabels: 'Storage:0.24928018,Service Bus:0.24577391,Cognitive - Computer Vision:0.04792439'

Thanks for the feedback! We are routing this to the appropriate team for follow-up. cc @xgithubtriage.

Issue Details

### Library name and version Microsoft.Azure.WebJobs.Extensions.Storage v4.0.5, v5.0.0 ### Query/Question In both track 1 and track 2 extensions for storage triggers, there is an internal timer, `CreateUpdateMessageVisibilityTimer`, which updates the queue message's `visibilityTimeout` property after half the `visibilityTimeout` has elapsed, as long as the function is still running and healthy, which allows a function to execute on a message for an arbitrary amount of time, without the message becoming visible again in the queue and picked up by another instance. The timer is created [here](https://github.com/Azure/azure-sdk-for-net/blob/d9f64791ffc2af0d4bfde75ad5b0e7d118f0e0e5/sdk/storage/Microsoft.Azure.WebJobs.Extensions.Storage.Common/src/Shared/Queues/QueueListener.cs#L411) and executed [here](https://github.com/Azure/azure-sdk-for-net/blob/cf175d9072e3bbf5013e9efa38a94d64fd30361e/sdk/storage/Microsoft.Azure.WebJobs.Extensions.Storage.Common/src/Shared/UpdateQueueMessageVisibilityCommand.cs#L47) for track 2, and created [here](https://github.com/Azure/azure-webjobs-sdk/blob/3f4ec78be9f43bb041937425ced00b341883aa42/src/Microsoft.Azure.WebJobs.Extensions.Storage/Queues/Listeners/QueueListener.cs#L366) and executed [here](https://github.com/Azure/azure-webjobs-sdk/blob/3f4ec78be9f43bb041937425ced00b341883aa42/src/Microsoft.Azure.WebJobs.Extensions.Storage/Queues/Listeners/UpdateQueueMessageVisibilityCommand.cs#L44) for track 1. However, I see different behavior for this timer between the two tracks, when examining the `NextVisibleTime`/`nextVisibleOn` of the `CloudQueueMessage`/`QueueMessage` object. In track 1, I see the property changes, but I don't see such a change using track 2. I have this simple queue trigger function to illustrate this behavior. Using track 1: ```C# [FunctionName("QueueTrigger1")] public async Task Run([QueueTrigger("test-queue", Connection = "connection")]CloudQueueMessage myQueueItem, ILogger log) { for (var i = 0; i < 20; i++) { log.LogInformation($"Minute {i}: nextVisibleTime: {myQueueItem.NextVisibleTime}, popReceipt: {myQueueItem.PopReceipt}"); await Task.Delay(60000); } } ``` When triggered, I see the following output: ``` [2022-02-07T21:55:57.273Z] Executing 'QueueTrigger1' (Reason='New queue message detected on 'test-queue'.', Id=da32acb1-2154-4033-b38b-b3ce5b51ca5d) [2022-02-07T21:55:57.280Z] Trigger Details: MessageId: 1617305c-f4e5-4479-bb86-a4c4692cd991, DequeueCount: 1, InsertionTime: 2022-02-07T21:55:56.000+00:00 [2022-02-07T21:55:57.325Z] Minute 0: nextVisibleTime: 2/7/2022 10:05:56 PM +00:00, popReceipt: AgAAAAMAAAAAAAAA+dpv4W4c2AE= [2022-02-07T21:56:57.336Z] Minute 1: nextVisibleTime: 2/7/2022 10:05:56 PM +00:00, popReceipt: AgAAAAMAAAAAAAAA+dpv4W4c2AE= [2022-02-07T21:57:57.345Z] Minute 2: nextVisibleTime: 2/7/2022 10:05:56 PM +00:00, popReceipt: AgAAAAMAAAAAAAAA+dpv4W4c2AE= [2022-02-07T21:58:57.359Z] Minute 3: nextVisibleTime: 2/7/2022 10:05:56 PM +00:00, popReceipt: AgAAAAMAAAAAAAAA+dpv4W4c2AE= [2022-02-07T21:59:57.379Z] Minute 4: nextVisibleTime: 2/7/2022 10:05:56 PM +00:00, popReceipt: AgAAAAMAAAAAAAAA+dpv4W4c2AE= [2022-02-07T22:00:57.396Z] Minute 5: nextVisibleTime: 2/7/2022 10:10:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAlAddlG8c2AEBAAAA [2022-02-07T22:01:57.412Z] Minute 6: nextVisibleTime: 2/7/2022 10:10:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAlAddlG8c2AEBAAAA [2022-02-07T22:02:57.423Z] Minute 7: nextVisibleTime: 2/7/2022 10:10:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAlAddlG8c2AEBAAAA [2022-02-07T22:03:57.450Z] Minute 8: nextVisibleTime: 2/7/2022 10:10:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAlAddlG8c2AEBAAAA [2022-02-07T22:04:57.457Z] Minute 9: nextVisibleTime: 2/7/2022 10:10:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAlAddlG8c2AEBAAAA [2022-02-07T22:05:57.464Z] Minute 10: nextVisibleTime: 2/7/2022 10:15:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAsjVBR3Ac2AEBAAAA [2022-02-07T22:06:57.478Z] Minute 11: nextVisibleTime: 2/7/2022 10:15:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAsjVBR3Ac2AEBAAAA [2022-02-07T22:07:57.517Z] Minute 12: nextVisibleTime: 2/7/2022 10:15:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAsjVBR3Ac2AEBAAAA [2022-02-07T22:08:57.532Z] Minute 13: nextVisibleTime: 2/7/2022 10:15:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAsjVBR3Ac2AEBAAAA [2022-02-07T22:09:57.543Z] Minute 14: nextVisibleTime: 2/7/2022 10:15:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAsjVBR3Ac2AEBAAAA [2022-02-07T22:10:57.557Z] Minute 15: nextVisibleTime: 2/7/2022 10:20:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAWKUi+nAc2AEBAAAA [2022-02-07T22:11:57.574Z] Minute 16: nextVisibleTime: 2/7/2022 10:20:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAWKUi+nAc2AEBAAAA [2022-02-07T22:12:57.596Z] Minute 17: nextVisibleTime: 2/7/2022 10:20:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAWKUi+nAc2AEBAAAA [2022-02-07T22:13:57.610Z] Minute 18: nextVisibleTime: 2/7/2022 10:20:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAWKUi+nAc2AEBAAAA [2022-02-07T22:14:57.622Z] Minute 19: nextVisibleTime: 2/7/2022 10:20:56 PM +00:00, popReceipt: AwAAAAMAAAAAAAAAWKUi+nAc2AEBAAAA [2022-02-07T22:15:57.699Z] Executed 'QueueTrigger1' (Succeeded, Id=da32acb1-2154-4033-b38b-b3ce5b51ca5d, Duration=1200486ms) ``` I can see the `NextVisibleTime` property change over time. However, when using track 2: ```C# [FunctionName("QueueTrigger1")] public async Task Run([QueueTrigger("test-queue", Connection = "connection")]QueueMessage myQueueItem, ILogger log) { for (var i = 0; i < 20; i++) { log.LogInformation($"Minute {i}: nextVisibleOn: {myQueueItem.NextVisibleOn}, popReceipt: {myQueueItem.PopReceipt}"); await Task.Delay(60000); } } ``` I see the following output: ``` [2022-02-07T23:57:19.232Z] Executing 'QueueTrigger1' (Reason='New queue message detected on 'test-queue'.', Id=6771e937-6079-41a1-827b-168ccbc2735b) [2022-02-07T23:57:19.236Z] Trigger Details: MessageId: e8b713c8-e03d-4485-bb72-925b3bcaf6ee, DequeueCount: 1, InsertedOn: 2022-02-07T23:57:16.000+00:00 [2022-02-07T23:57:19.289Z] Minute 0: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-07T23:57:22.560Z] Host lock lease acquired by instance ID '0000000000000000000000009AB4A82A'. [2022-02-07T23:58:19.314Z] Minute 1: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-07T23:59:19.328Z] Minute 2: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:00:19.351Z] Minute 3: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:01:19.367Z] Minute 4: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:02:19.390Z] Minute 5: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:03:19.398Z] Minute 6: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:04:19.445Z] Minute 7: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:05:19.460Z] Minute 8: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:06:19.487Z] Minute 9: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:07:19.508Z] Minute 10: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:08:19.516Z] Minute 11: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:09:19.538Z] Minute 12: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:10:19.555Z] Minute 13: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:11:19.574Z] Minute 14: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:12:19.585Z] Minute 15: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:13:19.606Z] Minute 16: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:14:19.613Z] Minute 17: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:15:19.637Z] Minute 18: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:16:19.659Z] Minute 19: nextVisibleOn: 2/8/2022 12:07:18 AM +00:00, popReceipt: AgAAAAMAAAAAAAAAyIzI1X8c2AE= [2022-02-08T00:17:19.811Z] Executed 'QueueTrigger1' (Succeeded, Id=6771e937-6079-41a1-827b-168ccbc2735b, Duration=1200700ms) ``` Sometimes it even causes the message to be visible and processed again, without any visible logs or warnings that updating the `visibilityTimeout` failed. For example: ``` [2022-02-07T22:51:26.365Z] Executing 'QueueTrigger1' (Reason='New queue message detected on 'test-queue'.', Id=8228ec1e-5a12-4d84-ba91-d919b01bcc74) [2022-02-07T22:51:26.371Z] Trigger Details: MessageId: 3a4cefa2-a37b-4055-8489-34297171bde2, DequeueCount: 1, InsertedOn: 2022-02-07T22:51:24.000+00:00 [2022-02-07T22:51:26.406Z] Minute 0: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T22:52:26.422Z] Minute 1: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T22:53:26.448Z] Minute 2: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T22:54:26.477Z] Minute 3: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T22:55:26.495Z] Minute 4: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T22:56:26.518Z] Minute 5: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T22:57:26.549Z] Minute 6: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T22:58:26.563Z] Minute 7: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T22:58:47.672Z] Executing 'QueueTrigger1' (Reason='New queue message detected on 'test-queue'.', Id=ee791174-f0bc-402c-b202-01f4eabc911b) [2022-02-07T22:58:47.674Z] Trigger Details: MessageId: 688a3631-b367-4748-8261-6a4de98cabac, DequeueCount: 2, InsertedOn: 2022-02-07T22:48:44.000+00:00 [2022-02-07T22:58:47.675Z] Minute 0: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE= [2022-02-07T22:59:26.575Z] Minute 8: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T22:59:47.681Z] Minute 1: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE= [2022-02-07T23:00:26.582Z] Minute 9: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T23:00:47.692Z] Minute 2: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE= [2022-02-07T23:01:26.590Z] Minute 10: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T23:01:47.711Z] Minute 3: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE= [2022-02-07T23:02:26.602Z] Minute 11: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T23:02:47.732Z] Minute 4: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE= [2022-02-07T23:03:26.620Z] Minute 12: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T23:03:47.740Z] Minute 5: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE= [2022-02-07T23:04:26.630Z] Minute 13: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T23:04:47.747Z] Minute 6: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE= [2022-02-07T23:05:26.651Z] Minute 14: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T23:05:47.779Z] Minute 7: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE= [2022-02-07T23:06:26.680Z] Minute 15: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= [2022-02-07T23:06:47.785Z] Minute 8: nextVisibleOn: 2/7/2022 11:08:46 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAQizYqHcc2AE= [2022-02-07T23:07:26.693Z] Minute 16: nextVisibleOn: 2/7/2022 11:01:25 PM +00:00, popReceipt: AgAAAAMAAAAAAAAAuVPEoXYc2AE= ``` In either case though, I don't see the `nextVisibleOn` property updating as time passes. Is this change in behavior to be expected? Is it documented somewhere? ### Environment Windows 10.0.22000 .NET SDK v6.0.101

Author:	hossam-nasr
Assignees:	-
Labels:	`Storage`, `Service Attention`, `needs-triage`
Milestone:	-

Label prediction was below confidence level 0.6 for Model:ServiceLabels: 'Storage:0.24928018,Service Bus:0.24577391,Cognitive - Computer Vision:0.04792439'

thanks for reporting this @hossam-nasr Hossam, we will look into this.

Hi @hossam-nasr, we deeply appreciate your input into this project. Regrettably, this issue has remained inactive for over 2 years, leading us to the decision to close it. We've implemented this policy to maintain the relevance of our issue queue and facilitate easier navigation for new contributors. If you still believe this topic requires attention, please feel free to create a new issue, referencing this one. Thank you for your understanding and ongoing support.

Azure / azure-sdk-for-net