Queue messages completed when web job in 'disabling' state are put back on the queue

[janzakrzewskipl]

I am running web job sdk (v 2.0.0) and using QueueTrigger attribute. I wanted to give my messages more time when I am stopping/deploying web job, so I used { "stopping_wait_time": 60 } setting in settings.job file which works great. Unfortunately I observed that messages that complete in that extra time when web job is shutting down are not treated as executed correctly (and they appear on the queue again after sometime) even though they are fully processed.

My code looks like that:

public async Task ProcessQueueMessage([QueueTrigger("Queue1")] string message, TextWriter log, CancellationToken cancellationToken)
{

    var stopwatch = Stopwatch.StartNew();
    Logger.LogDebug("New message from queue: {Message}", message);

    var seconds = int.Parse(message);
    await Task.Delay(TimeSpan.FromSeconds(seconds));

    Logger.LogDebug("Finished processing message: {Message}. Duration: {Duration}ms", message, stopwatch.ElapsedMilliseconds);
}

Dashboard shows that messages never finished:

But from logs I see they finished:

[05/30/2017 11:28:02 : INFO] [11:28:02 DBG] Finished processing message: 5. Duration: 5010ms
[05/30/2017 11:28:04 : SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[05/30/2017 11:28:04 : SYS INFO] Status changed to Stopping
[05/30/2017 11:28:07 : SYS INFO] Status changed to Disabling
[05/30/2017 11:28:16 : INFO] [11:28:16 DBG] Finished processing message: 20. Duration: 20008ms
[05/30/2017 11:28:27 : INFO] [11:28:27 DBG] Finished processing message: 30. Duration: 30010ms
[05/30/2017 11:28:36 : INFO] [11:28:36 DBG] Finished processing message: 40. Duration: 40012ms
[05/30/2017 11:28:46 : INFO] [11:28:46 DBG] Finished processing message: 50. Duration: 50023ms
[05/30/2017 11:28:47 : INFO] [11:28:47 DBG] Finished processing message: 50. Duration: 50017ms
[05/30/2017 11:29:04 : ERR ] Thread was being aborted.
[05/30/2017 11:29:04 : SYS INFO] WebJob process was aborted
[05/30/2017 11:29:04 : SYS INFO] Status changed to Stopped
[05/30/2017 11:29:07 : SYS INFO] Detected WebJob file/s were updated, refreshing WebJob

Am I missing something here?

[paulbatum]

@MikeStall any ideas on this one?

[paulbatum]

So this is problematic not just because of the state shown in the dashboard but because the messages were put back on the queue, which definitely does not seem correct.