Queued Item marked invisible after idle time/redeploy of code.

[rndthoughts]

Provide the steps required to reproduce the problem

1. Create a Function app with a queuetrigger.
2. Run the function on a consumption plan.
3. Trigger the function with a correctly typed queue entry. The message is processed and removed fromt the queue correctly.
4. Leave the queue empty for 20-30 mins.
5. Add a new valid queue entry as per step 2.
6. After a period of time, the trigger fires but the message is immediately hidden in queue (status shows 0 of 1 items) in Storage Explorer.
7. Wait around 10-15 minutes and the message reappears and is processed correctly.

Expected behavior

The queue message is processed and removed from the queue both when the queue busy and quiet.

Actual behavior

If the server backs off and idles, the message is hidden and processed 10-15 mins later. This also occurs when a new version of the underlying code is published. If i add another item to the queue it is processed correctly and removed while the hidden one is still present. When the hidden message reappears, it too is processed correctly and removed.

Known workarounds

Unknown

Other info

Logging and application insights show no exceptions or errors. The job restarts correctly when code changes are detected. I cannot find any log entries regarding the hiding of the initial message.

[rndthoughts]

Further Info:

Using Application Insights, I can see the host starting successfully, it detects the queued item, runs through all my code and outputs all the log statements all the way to the end of the function. Then this happens:

An unhandled exception has occurred. Host is shutting down.
Failed method
System.Threading.CancellationTokenSource.ThrowObjectDisposedException

Stack Trace logged by AppInsights:

System.ObjectDisposedException:
   at System.Threading.CancellationTokenSource.ThrowObjectDisposedException (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Threading.CancellationTokenSource.InternalRegister (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Threading.CancellationToken.Register (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Threading.CancellationToken.Register (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at Microsoft.Azure.WebJobs.Host.Timers.TaskSeriesTimer+<StopAsyncCore>d__11.MoveNext (Microsoft.Azure.WebJobs.Host, Version=2.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at Microsoft.Azure.WebJobs.Host.Queues.Listeners.QueueListener+<ProcessMessageAsync>d__26.MoveNext (Microsoft.Azure.WebJobs.Host, Version=2.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35)

I have a try..catch block around all my code with a logging statement to output any exceptions that my code causes but nothing gets output by it. Therefore it's something weird with the host?

[brettsam]

Thanks for the report @rndthoughts.

Would you mind sharing:

• Your function app name, either directly or indirectly.
• A timeframe where you've seen this happen.
• Your function code (with any secrets removed).

[rndthoughts]

Hi Brett,

Thanks for responding.

1. Function App Name is "uk-live-ueazfunctions.azurewebsites.net"
2. Timeframe - occurs everytime I drop a correctly formatted message into the trigger queue either after the app has idled or after I publish a new version of the code.
3. Can i give you access to my vsts repo so that you can see the code? I'd rather not post the source code on here.

Steve

[brettsam]

Thanks! I'll take your site info and try to see if I can find anything in our logs that looks suspect. If I think I need more info, we can try adding me to your VSTS repo.

[brettsam]

It's not clear where the ObjectDisposedExceptions are coming from -- would you be able to add me to your repo? You can find my work email in my Github profile. Is that all you need?

[rndthoughts]

I tried adding you to our VSTS git repo but as it's backed by Azure AD I can only add your account if it's a "Microsoft Account" - which ironically yours doesn't appear to be! Do you have an MS account I can add? If not, how else can I get a copy of the files to you securely?

[brettsam]

Try using my same email alias, but @outlook.com. Worst case, you could zip things up and email me to that microsoft email account.

[rndthoughts]

OK you should be able to get to the repo now: https://updateedge.visualstudio.com/_git/AzureFunctions

I've just literally taken a copy of the project files from the solution and added them to a new repo for to look at. It doesnt compile in its current state as I havent fixed nuget, etc but the source code is identical.

ClientApiUpdates is the function causing the problem.

[brettsam]

Thanks! I see it -- taking a look now.

[brettsam]

First thing I noticed -- your async function methods need to return a Task rather than void. Without a Task, we don't have anything to wait on and odd stuff can start to happen.

I'd also recommend switching the calls to Query to use an async version, if it's available (I wasn't sure if that was an extension method; I couldn't find it in the docs). You should always go async whenever you can, especially with calls to other services.

I think that changing your return type to Task will make it clearer what's happening -- can you let me know?

[rndthoughts]

I can't believe I didn't spot I wasn't using Task! I have implemented the changes and redeployed. The log output seems to indicate that the function is firing twice for some reason? I have verified only one message is going into the queue. You can see below, we have duplicate output statements appearing with the same timestamps? The queued item has disappeared now though and is no longer hidden.

UPDATE: I have tried this just after deployment and after queue idle and get the same result.

2017-06-26T08:32:07.356 Function started (Id=21b6c23e-b820-4ec5-8be2-270dacbb8e86)
2017-06-26T08:32:07.371 Started client api processing for userId: 1fdecea9-306a-4d0f-be43-9c5736b2085b
2017-06-26T08:32:07.403 Current timestamp is '{currentTimestamp}'
2017-06-26T08:32:07.419 Found 1 clients authorized to receive data for userId: 1fdecea9-306a-4d0f-be43-9c5736b2085b
2017-06-26T08:32:07.419 Retrieving events for client: redactedClientName with userId: 1fdecea9-306a-4d0f-be43-9c5736b2085b
2017-06-26T08:32:07.434 Found 1 event(s) to send to client 'redactedClientName' for user '1fdecea9-306a-4d0f-be43-9c5736b2085b'
2017-06-26T08:32:07.434 Created apiEvent objects successfully
2017-06-26T08:32:07.762 [{"id":"2d7e6898-4f55-4506-ae10-8ec61e1a7010","userId":"1fdecea9-306a-4d0f-be43-9c5736b2085b","eventType":1,"start":"2017-07-06T08:00:00+00:00","end":"2017-07-06T17:00:00+00:00","repeatTypeId":0,"repeatUntil":"0001-01-01T00:00:00+00:00","repeatForever":false,"repeatType":0,"deleted":false,"createdAt":"2017-06-26T08:31:58.0882231+00:00","updatedAt":"2017-06-26T08:32:00.2609834+00:00"}]
2017-06-26T08:32:07.762 Serialized apiEvent objects successfully
2017-06-26T08:32:07.356 Executing 'Functions.ClientApiUpdates' (Reason='New queue message detected on 'api-event-update'.', Id=21b6c23e-b820-4ec5-8be2-270dacbb8e86)
2017-06-26T08:32:07.356 Function started (Id=21b6c23e-b820-4ec5-8be2-270dacbb8e86)
2017-06-26T08:32:07.371 Started client api processing for userId: 1fdecea9-306a-4d0f-be43-9c5736b2085b
2017-06-26T08:32:07.403 Current timestamp is '{currentTimestamp}'
2017-06-26T08:32:07.419 Found 1 clients authorized to receive data for userId: 1fdecea9-306a-4d0f-be43-9c5736b2085b
2017-06-26T08:32:07.419 Retrieving events for client: redactedClientName with userId: 1fdecea9-306a-4d0f-be43-9c5736b2085b
2017-06-26T08:32:07.434 Found 1 event(s) to send to client 'redactedClientName' for user '1fdecea9-306a-4d0f-be43-9c5736b2085b'
2017-06-26T08:32:07.434 Created apiEvent objects successfully
2017-06-26T08:32:07.762 [{"id":"2d7e6898-4f55-4506-ae10-8ec61e1a7010","userId":"1fdecea9-306a-4d0f-be43-9c5736b2085b","eventType":1,"start":"2017-07-06T08:00:00+00:00","end":"2017-07-06T17:00:00+00:00","repeatTypeId":0,"repeatUntil":"0001-01-01T00:00:00+00:00","repeatForever":false,"repeatType":0,"deleted":false,"createdAt":"2017-06-26T08:31:58.0882231+00:00","updatedAt":"2017-06-26T08:32:00.2609834+00:00"}]
2017-06-26T08:32:07.762 Serialized apiEvent objects successfully
2017-06-26T08:32:08.012 POST succeeded: True
2017-06-26T08:32:08.012 Updating Client LastUpdated value for user: 1fdecea9-306a-4d0f-be43-9c5736b2085b
2017-06-26T08:32:08.028 Completed client api update for userId: 1fdecea9-306a-4d0f-be43-9c5736b2085b
2017-06-26T08:32:08.028 Function completed (Success, Id=21b6c23e-b820-4ec5-8be2-270dacbb8e86, Duration=670ms)
2017-06-26T08:32:08.012 POST succeeded: True
2017-06-26T08:32:08.012 Updating Client LastUpdated value for user: 1fdecea9-306a-4d0f-be43-9c5736b2085b
2017-06-26T08:32:08.028 Completed client api update for userId: 1fdecea9-306a-4d0f-be43-9c5736b2085b
2017-06-26T08:32:08.028 Function completed (Success, Id=21b6c23e-b820-4ec5-8be2-270dacbb8e86, Duration=670ms)
2017-06-26T08:32:08.028 Executed 'Functions.ClientApiUpdates' (Succeeded, Id=21b6c23e-b820-4ec5-8be2-270dacbb8e86)

[brettsam]

If you look at the Ids, it looks like you're seeing duplicate logs, not duplicate function invocations. Where are you seeing these logs? Was it in the portal, or on the file system itself?

[rndthoughts]

I was using Log file streaming on the portal. However, I just downloaded the .log file using FTP and I can see the same duplicate output in there too. I am using the textwriter object. It only seems to duplicate log on this function for some reason - my other ones don't.

[brettsam]

I've opened #1627 to track that as it's a separate issue.

Besides the logging, is this now working as you'd expect? If so, I can close out this issue and investigate the logging duplications.

[rndthoughts]

Yes, thank you for your time and patience on this :) I haven't see any more instances of it marking messages hidden. Just for my sanity, do you think it's the lack of the Task keyword that was causing the issue?

[brettsam]

I've been trying to reproduce it and haven't been able to hit it, which makes me think there's some kind of race condition going on with your function when you don't return a Task. When you return void, the function will assume it is done the first time that you await anything. So your code looks like it executes a few queries, then awaits the HTTP call, then possibly continues looping with more queries and HTTP calls (once per client). Our internal CancellationToken must be getting disposed and then accessed again later somewhere in there, and I'm not sure why. I'm trying to work through it but without being able to repro it locally, it's been tough.

I'm going to give it some more thought b/c I want to know exactly what's happening, but I'll close this issue since I think we've figured out how to get you running again.

[brettsam]

One more follow up -- how have you been publishing your changes?

[rndthoughts]

I use VSTS release to publish the code via webdeploy.