azure-webjobs-sdk-extensions icon indicating copy to clipboard operation
azure-webjobs-sdk-extensions copied to clipboard

Published 20 hours ago • verified publisher icon Azure

Singleton lock renewal failed

Open heltime opened this issue 7 years ago • 24 comments

Hi, I have a long-running time triggered WebJob (takes about 3-4 hrs to complete) that frequently throws the following exception:

Microsoft.WindowsAzure.Storage.StorageException: The client could not finish the operation within specified timeout. ---> System.TimeoutException: The client could not finish the operation within specified timeout.

Prior to the exception being thrown, there is a system info message in the log:

Singleton lock renewal failed for blob '3e0dca7...' with error code 408. The last successful renewal completed at 2017-07-04T11:29:13.084Z (1491813 milliseconds ago) with a duration of 389 milliseconds. The lease period was 60000 milliseconds.

The web job trigger is

[TimerTrigger("06:00:00", RunOnStartup = true)] TimerInfo timerInfo

I suppose there is a timeout setting that needs to be prolonged? I have played around a bit with the JobHostConfiguration.Singleton properties, but have not found any that solves my problem. Is there any documentation that I may have missed, or other tips that can point me in the right direction here?

Full stack trace:

[07/04/2017 11:57:49 > 997459: ERR ] Unhandled Exception: Microsoft.WindowsAzure.Storage.StorageException: The client could not finish the operation within specified timeout. ---> System.TimeoutException: The client could not finish the operation within specified timeout.
[07/04/2017 11:57:49 > 997459: ERR ]    --- End of inner exception stack trace ---
[07/04/2017 11:57:49 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.EndExecuteAsync[T](IAsyncResult result) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Executor\Executor.cs:line 50
[07/04/2017 11:57:49 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Queue.CloudQueue.EndExists(IAsyncResult asyncResult) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Queue\CloudQueue.cs:line 1027
[07/04/2017 11:57:49 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions.<>c__DisplayClass1`1.<CreateCallback>b__0(IAsyncResult ar) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Util\AsyncExtensions.cs:line 66
[07/04/2017 11:57:49 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:49 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[07/04/2017 11:57:49 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[07/04/2017 11:57:49 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.Queues.Listeners.QueueListener.<ExecuteAsync>d__21.MoveNext()
[07/04/2017 11:57:49 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:49 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[07/04/2017 11:57:49 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[07/04/2017 11:57:49 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.Timers.TaskSeriesTimer.<RunAsync>d__14.MoveNext()
[07/04/2017 11:57:49 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:50 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.Timers.WebJobsExceptionHandler.<>c__DisplayClass3_0.<OnUnhandledExceptionAsync>b__0()
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Threading.ThreadHelper.ThreadStart()
[07/04/2017 11:57:50 > 997459: ERR ] Microsoft.WindowsAzure.Storage.StorageException: The client could not finish the operation within specified timeout. ---> System.TimeoutException: The client could not finish the operation within specified timeout.
[07/04/2017 11:57:50 > 997459: ERR ]    --- End of inner exception stack trace ---
[07/04/2017 11:57:50 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.EndExecuteAsync[T](IAsyncResult result) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Executor\Executor.cs:line 50
[07/04/2017 11:57:50 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Blob.CloudBlob.EndRenewLease(IAsyncResult asyncResult) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlob.cs:line 1979
[07/04/2017 11:57:50 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions.<>c__DisplayClass4.<CreateCallbackVoid>b__3(IAsyncResult ar) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Util\AsyncExtensions.cs:line 114
[07/04/2017 11:57:50 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[07/04/2017 11:57:50 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.SingletonManager.RenewLeaseCommand.<ExecuteAsync>d__9.MoveNext()
[07/04/2017 11:57:50 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[07/04/2017 11:57:50 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.Timers.TaskSeriesTimer.<RunAsync>d__14.MoveNext()
[07/04/2017 11:57:50 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:50 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.Timers.WebJobsExceptionHandler.<>c__DisplayClass3_0.<OnUnhandledExceptionAsync>b__0()
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
[07/04/2017 11:57:50 > 997459: ERR ]    at System.Threading.ThreadHelper.ThreadStart()
[07/04/2017 11:57:50 > 997459: ERR ] Microsoft.WindowsAzure.Storage.StorageException: The client could not finish the operation within specified timeout. ---> System.TimeoutException: The client could not finish the operation within specified timeout.
[07/04/2017 11:57:50 > 997459: ERR ]    --- End of inner exception stack trace ---
[07/04/2017 11:57:51 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Core.Util.StorageAsyncResult`1.End() in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Util\StorageAsyncResult.cs:line 77
[07/04/2017 11:57:51 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadFromStream(IAsyncResult asyncResult) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlockBlob.cs:line 742
[07/04/2017 11:57:51 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadFromByteArray(IAsyncResult asyncResult) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlockBlob.cs:line 1083
[07/04/2017 11:57:51 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadText(IAsyncResult asyncResult) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlockBlob.cs:line 1206
[07/04/2017 11:57:51 > 997459: ERR ]    at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions.<>c__DisplayClass4.<CreateCallbackVoid>b__3(IAsyncResult ar) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Util\AsyncExtensions.cs:line 114
[07/04/2017 11:57:51 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:51 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[07/04/2017 11:57:51 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[07/04/2017 11:57:51 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.Loggers.UpdateOutputLogCommand.<UpdateOutputBlob>d__18.MoveNext()
[07/04/2017 11:57:51 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:51 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[07/04/2017 11:57:51 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[07/04/2017 11:57:51 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.Loggers.UpdateOutputLogCommand.<TryExecuteAsync>d__14.MoveNext()
[07/04/2017 11:57:51 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:51 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[07/04/2017 11:57:51 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[07/04/2017 11:57:51 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.Timers.RecurrentTaskSeriesCommand.<ExecuteAsync>d__3.MoveNext()
[07/04/2017 11:57:52 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:52 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[07/04/2017 11:57:52 > 997459: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[07/04/2017 11:57:52 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.Timers.TaskSeriesTimer.<RunAsync>d__14.MoveNext()
[07/04/2017 11:57:52 > 997459: ERR ] --- End of stack trace from previous location where exception was thrown ---
[07/04/2017 11:57:52 > 997459: ERR ]    at Microsoft.Azure.WebJobs.Host.Timers.WebJobsExceptionHandler.<>c__DisplayClass3_0.<OnUnhandledExceptionAsync>b__0()
[07/04/2017 11:57:52 > 997459: ERR ]    at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
[07/04/2017 11:57:52 > 997459: ERR ]    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
[07/04/2017 11:57:52 > 997459: ERR ]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
[07/04/2017 11:57:52 > 997459: ERR ]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
[07/04/2017 11:57:52 > 997459: ERR ]    at System.Threading.ThreadHelper.ThreadStart()
[07/04/2017 11:57:53 > 997459: SYS ERR ] Job failed due to exit code -532462766
[07/04/2017 11:57:53 > 997459: SYS INFO] Process went down, waiting for 0 seconds

heltime avatar Jul 15 '17 08:07 heltime

We're having the same issue. Singletone job with timer trigger Stacktrace from application logs:

The process was terminated due to an unhandled exception. Exception Info: System.Net.WebException 
   at Microsoft.WindowsAzure.Storage.Shared.Protocol.HttpResponseParsers.ProcessExpectedStatusCodeNoException[[System.__Canon, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089]](System.Net.HttpStatusCode, System.Net.HttpStatusCode, System.__Canon, Microsoft.WindowsAzure.Storage.Core.Executor.StorageCommandBase`1<System.__Canon>, System.Exception) 
   at Microsoft.WindowsAzure.Storage.Blob.CloudBlob+<>c__DisplayClass3d.<RenewLeaseImpl>b__3c(Microsoft.WindowsAzure.Storage.Core.Executor.RESTCommand`1<Microsoft.WindowsAzure.Storage.Core.NullType>, System.Net.HttpWebResponse, System.Exception, Microsoft.WindowsAzure.Storage.OperationContext) 
   at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.EndGetResponse[[System.__Canon, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089]](System.IAsyncResult)  Exception Info: Microsoft.WindowsAzure.Storage.StorageException 
   at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.EndExecuteAsync[[System.__Canon, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089]](System.IAsyncResult) 
   at Microsoft.WindowsAzure.Storage.Blob.CloudBlob.EndRenewLease(System.IAsyncResult) 
   at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions+<>c__DisplayClass4.<CreateCallbackVoid>b__3(System.IAsyncResult) 
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(System.Threading.Tasks.Task) 
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task) 
   at Microsoft.Azure.WebJobs.Host.SingletonManager+RenewLeaseCommand+<ExecuteAsync>d__9.MoveNext() 
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(System.Threading.Tasks.Task) 
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task) 
   at Microsoft.Azure.WebJobs.Host.Timers.TaskSeriesTimer+<RunAsync>d__14.MoveNext() 
   at Microsoft.Azure.WebJobs.Host.Timers.WebJobsExceptionHandler+<>c__DisplayClass3_0.<OnUnhandledExceptionAsync>b__0() 
   at System.Threading.ThreadHelper.ThreadStart_Context(System.Object) 
   at System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) 
   at System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) 
   at System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 
   at System.Threading.ThreadHelper.ThreadStart()

alex-zyl avatar Oct 24 '17 14:10 alex-zyl

+1 Long running Web job with timer trigger

 Singleton lock renewal failed for blob '***' with error code 408. The last successful renewal completed at 2017-11-09T10:05:14.566Z (351422 milliseconds ago) with a duration of 1074293 milliseconds. The lease period was 60000 milliseconds.
[11/09/2017 10:11:22 > e7010c: ERR ] 
[11/09/2017 10:11:22 > e7010c: ERR ] Unhandled Exception: Microsoft.WindowsAzure.Storage.StorageException: The client could not finish the operation within specified timeout. ---> System.TimeoutException: The client could not finish the operation within specified timeout.
[11/09/2017 10:11:22 > e7010c: ERR ]    --- End of inner exception stack trace ---
[11/09/2017 10:11:22 > e7010c: ERR ]    at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.EndExecuteAsync[T](IAsyncResult result) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Executor\Executor.cs:line 50
[11/09/2017 10:11:22 > e7010c: ERR ]    at Microsoft.WindowsAzure.Storage.Blob.CloudBlob.EndRenewLease(IAsyncResult asyncResult) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlob.cs:line 2174
[11/09/2017 10:11:22 > e7010c: ERR ]    at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions.<>c__DisplayClass4.<CreateCallbackVoid>b__3(IAsyncResult ar) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Util\AsyncExtensions.cs:line 114
[11/09/2017 10:11:22 > e7010c: ERR ] --- End of stack trace from previous location where exception was thrown ---
[11/09/2017 10:11:22 > e7010c: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[11/09/2017 10:11:22 > e7010c: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[11/09/2017 10:11:22 > e7010c: ERR ]    at Microsoft.Azure.WebJobs.Host.SingletonManager.RenewLeaseCommand.<ExecuteAsync>d__9.MoveNext()
[11/09/2017 10:11:22 > e7010c: ERR ] --- End of stack trace from previous location where exception was thrown ---
[11/09/2017 10:11:22 > e7010c: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[11/09/2017 10:11:22 > e7010c: ERR ]    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[11/09/2017 10:11:22 > e7010c: ERR ]    at Microsoft.Azure.WebJobs.Host.Timers.TaskSeriesTimer.<RunAsync>d__14.MoveNext()
[11/09/2017 10:11:22 > e7010c: ERR ] --- End of stack trace from previous location where exception was thrown ---
[11/09/2017 10:11:22 > e7010c: ERR ]    at Microsoft.Azure.WebJobs.Host.Timers.WebJobsExceptionHandler.<>c__DisplayClass3_0.<OnUnhandledExceptionAsync>b__0()
[11/09/2017 10:11:22 > e7010c: ERR ]    at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
[11/09/2017 10:11:22 > e7010c: ERR ]    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
[11/09/2017 10:11:22 > e7010c: ERR ]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
[11/09/2017 10:11:22 > e7010c: ERR ]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
[11/09/2017 10:11:22 > e7010c: ERR ]    at System.Threading.ThreadHelper.ThreadStart()
[11/09/2017 10:11:24 > e7010c: SYS ERR ] Job failed due to exit code -532462766

maks-bondarenko avatar Nov 09 '17 10:11 maks-bondarenko

@mathewc - would you happen to know who owns this feature area?

captainnumerica avatar Dec 21 '17 18:12 captainnumerica

+1

long running job with http trigger:

Singleton lock renewal failed for blob 'locks/jdhussp/host' with error code 409: LeaseIdMismatchWithLeaseOperation. The last successful renewal completed at 2017-12-22T17:10:41.638Z (191191 milliseconds ago) with a duration of 0 milliseconds. The lease period was 15000 milliseconds.

Failed to renew host lock lease: Another host has acquired the lease. The last successful renewal completed at 2017-12-22T17:10:41.638Z (193149 milliseconds ago) with a duration of 0 milliseconds.

kmosti avatar Dec 22 '17 19:12 kmosti

Also seeing some cases where lease renewal fails with a 409 conflict without the host having ever had a successful renewal:

Singleton lock renewal failed for blob 'MyApp.Listener' with error code 409: LeaseIdMismatchWithLeaseOperation. The last successful renewal completed at 0001-01-01T00:00:00Z (-2147483648 milliseconds ago) with a duration of 0 milliseconds. The lease period was 60000 milliseconds.

The above case is from ICM #73620266. Analysis of the VM where the lease was lost showed the CPU at only 20%, so the usual explanation for this of the background refresh failing to run because the TaskScheduler is too busy may not apply.

I think we should improve the error message above in the following ways, to help people self diagnose/fix these issues:

  • include a link to the TSG https://github.com/Azure/azure-webjobs-sdk-extensions/wiki/TimerTrigger#troubleshooting
  • update the error so in the case where no updates were ever performed, we're not showing a negative number/zero like above. It makes the error look wrong.

Moving this back to triage.

mathewc avatar Jun 22 '18 02:06 mathewc

Adding this to triaged so the enhancements above can be made.

fabiocav avatar Jul 05 '18 18:07 fabiocav

I would like to add a similar situation with durable functions (V1). I have a timer function which runs once every 24 hours with RunOnStartup = false, UseMonitor = true parameters. It writes to a service bus topic which invokes a DurableOrchestrationClient function. The client function invokes Orchestrator to fan out to activity functions. In my case, there is no overlap of the timer function between schedules because the timer function completes fairly quickly and is not supposed to run until the next day. All the functions are on the consumption plan under the same host. I get below error which is very misleading. I guess the issue is something else but the error message is not clear enough to point in right direction.

Singleton lock renewal failed for blob 'function-dashboard-storage/somenamespace.someclass.Run.Listener' with error code 409: LeaseIdMismatchWithLeaseOperation. The last successful renewal completed at 2018-09-03T11:28:10.042Z (34659 milliseconds ago) with a duration of 36610 milliseconds. The lease period was 15000 milliseconds. severityLevel 3 itemType trace sdkVersion azurefunctions: 1.0.11959.0

Also, below error alternates with above

Singleton lock renewal failed for blob 'locks/functionname/host' with error code 409: LeaseIdMismatchWithLeaseOperation. The last successful renewal completed at 2018-09-03T11:44:29.245Z (21784 milliseconds ago) with a duration of 13641 milliseconds. The lease period was 15000 milliseconds.

AbhishekTripathi avatar Sep 03 '18 11:09 AbhishekTripathi

Hiya, my team is seeing this same issue with v3.0.0. Is this detrimental to how webjobs function or hinder their reliability in any way? It doesn't appear like it (I still see it running like it should) but it is an error, so I'd like some idea on what the impact is :)

blackbaud-jeremymorgan avatar Oct 25 '18 15:10 blackbaud-jeremymorgan

I have similar situation and the impact any running job is failed because process is killed and webjob restarts - see stack trace below.

[01/01/2019 06:03:35 > 8e66ee: INFO] Singleton lock renewal failed for blob 'bf25a72f7b4b45c4ac170b89bec88f2d/WebJobs.Internal.Blobs.Listener' with error code 409: LeaseIdMismatchWithLeaseOperation. The last successful renewal completed at 2019-01-01T06:02:29.137Z (66676 milliseconds ago) with a duration of 26933 milliseconds. The lease period was 60000 milliseconds. [01/01/2019 06:03:36 > 8e66ee: ERR ] at Microsoft.Azure.WebJobs.Host.Timers.TaskSeriesTimer.<RunAsync>d__14.MoveNext() [01/01/2019 06:03:36 > 8e66ee: ERR ] --- End of stack trace from previous location where exception was thrown --- [01/01/2019 06:03:36 > 8e66ee: ERR ] at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() [01/01/2019 06:03:36 > 8e66ee: ERR ] at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) [01/01/2019 06:03:36 > 8e66ee: ERR ] at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) [01/01/2019 06:03:36 > 8e66ee: ERR ] at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) [01/01/2019 06:03:36 > 8e66ee: ERR ] at System.Threading.ThreadHelper.ThreadStart() [01/01/2019 06:03:36 > 8e66ee: SYS ERR ] Job failed due to exit code -532462766 [01/01/2019 06:03:36 > 8e66ee: SYS INFO] Process went down, waiting for 0 seconds [01/01/2019 06:03:36 > 8e66ee: SYS INFO] Status changed to PendingRestart [01/01/2019 06:03:36 > 8e66ee: SYS INFO] Run script 'run.exe' with script host - 'WindowsScriptHost' [01/01/2019 06:03:36 > 8e66ee: SYS INFO] Status changed to Running [01/01/2019 06:03:38 > 8e66ee: INFO] [06:03:38 INF] [CCWebJobs:1] Main: WebJobs Main()

MNaveedKhalid avatar Jan 01 '19 06:01 MNaveedKhalid

I'm also getting something similar. I have Storage Queue triggers in the function app only. App Insights shows:

Singleton lock renewal failed for blob 'functionname/host' with error code 409: LeaseIdMismatchWithLeaseOperation. The last successful renewal completed at 2019-01-18T10:33:17.137Z (10896 milliseconds ago) with a duration of 48857 milliseconds. The lease period was 15000 milliseconds.

followed by:

Failed to renew host lock lease: Another host has acquired the lease. The last successful renewal completed at 2019-01-18T10:33:17.137Z (10898 milliseconds ago) with a duration of 48857 milliseconds.

Then the entire app seems to fall over and I get a slew of errors with the message:

The operation was canceled.

I'm trying to collect the stack trace for that error but it doesn't look like we're currently logging it. I'll update this with the more detailed exception if/when I have it.

stap123 avatar Jan 18 '19 13:01 stap123

Hi all, we are also getting the following webjob errors. The log says 👍

[02/18/2019 02:55:01 > 2f460e: INFO] dbug: Host.Singleton[0] [02/18/2019 02:55:01 > 2f460e: INFO] Unable to acquire Singleton lock (5e372e70ee678958c6f655d625888fee/NP.WebJob.EmailLoader.Functions.Run.Listener). [02/18/2019 02:55:01 > 2f460e: INFO] Application started. Press Ctrl+C to shut down.

We have a number of webjobs and if only one is active then it gets the singleton lock upon startup , the remaining seem to get this error and therefore will not run as expected.

It would be great to have some clarification on what is the cause of this eg can > 1 webjob use the same default host? can i sent the webjob host upon startup ?

markvl2 avatar Feb 18 '19 03:02 markvl2

The same here while working with Azure Functions QueueTrigger and trying to create a file in the file system:

using (var file = File.CreateText($"{context.FunctionAppDirectory}/dir12/file1.json"))
{
//
}

I am always getting:

[26/07/2019 09:09:20] A ScriptHost error has occurred [26/07/2019 09:09:20] Singleton lock renewal failed for blob 'locks/gfit0222-1863217941/host' with error code 409: LeaseIdMismatchWithLeaseOperation. The last successful renewal completed at 0001-01-01T00:00:00Z (-2147483648 milliseconds ago) with a duration of 0 milliseconds. The lease period was 15000 milliseconds. [26/07/2019 09:09:20] Singleton lock renewal failed for blob 'locks/gfit0222-1863217941/host' with error code 409: LeaseIdMismatchWithLeaseOperation. The last successful renewal completed at 0001-01-01T00:00:00Z (-2147483648 milliseconds ago) with a duration of 0 milliseconds. The lease period was 15000 milliseconds.

marzoukali avatar Jul 26 '19 09:07 marzoukali

I'm seeing this error with a long-running, scaled-up set of the latest 2.0 azure node functions runtime docker image using a blob trigger:

Singleton lock renewal failed for blob '***-functions/host' with error code 409: LeaseIdMismatchWithLeaseOperation. The last successful renewal completed at 2019-10-27T16:12:10.853Z (17048 milliseconds ago) with a duration of 4 milliseconds. The lease period was 15000 milliseconds.

Just after seeing this message, blob trigger processing of new blobs stops. Restarting 1 of the 8 functions containers did not cause processing to resume, though the restarted container did not issue any error messages, about locks or otherwise. Picking another 3 of the 8 functions containers, effectively at random, and restarting them caused new blob processing to resume.

derekrprice avatar Oct 28 '19 15:10 derekrprice

Anyone have any idea what may be causing this? We're still seeing it. It appears to occur pretty consistently and once we see the error, processing in our 6 concurrently running containers stops, usually for many hours.

derekrprice avatar Nov 15 '19 12:11 derekrprice

Same for us. We see this all the time in the logs.

zmarty avatar Jan 28 '20 19:01 zmarty

We are seeing these a lot too. But the weird thing is, we have a dev and prod environment, and they only appear in dev. The two environments should be the same. Edit: They also appear in prod, although not as frequent.

Neophear avatar Feb 13 '20 08:02 Neophear

I see errors like this all the time too. Different instances like:

Singleton lock renewal failed for blob 'myfunction/someblogname' with error code 306

and:

Singleton lock renewal failed for blob 'myfunction/someblogname' with error code 409: LeaseIdMismatchWithLeaseOperation

It would be nice with an official statement if these errors can be ignored or not. And even better to fix these errors and/or switch the log statements to use structured logging properties for dates and other changing things embedded into the log message. When embedding dates, function names, blog names, and error codes into the log message, it is considered a unique error every time it happens.

ThomasArdal avatar Apr 29 '20 08:04 ThomasArdal

I'm troubleshooting some bizarre problems with serverless functions we recently introduced into the mix, and we seem to have the same problem!

And it looks like this is a very long running issue here... quite surprising no one at Msft has provided any feedback or guidance here! :( Does this affect all function azure functions runtime versions?

Our case is a storage queue triggered function... which can sometimes run for 5-10 minutes. We're on v1 of function runtime sdk.

Host file

10:20:19 PM
Singleton lock renewal failed for blob 'locks/myfunction/host' with error code 408. The last successful renewal completed at 2020-04-30T02:08:47.096Z (691780 milliseconds ago) with a duration of 0 milliseconds. The lease period was 15000 milliseconds.

10:20:19 PM
Failed to renew host lock lease: Another host has acquired the lease. The last successful renewal completed at 2020-04-30T02:08:47.096Z (692296 milliseconds ago) with a duration of 0 milliseconds.

10:25:23 PM
An unhandled exception has occurred. Host is shutting down.

10:25:23 PM
The client could not finish the operation within specified timeout.
**Exception Type:** Microsoft.WindowsAzure.Storage.StorageException

Microsoft.WindowsAzure.Storage.StorageException: The client could not finish the operation within specified timeout. ---> System.TimeoutException: The client could not finish the operation within specified timeout.
   --- End of inner exception stack trace ---
   at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.EndExecuteAsync[T](IAsyncResult result) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Executor\Executor.cs:line 50
   at Microsoft.WindowsAzure.Storage.Queue.CloudQueue.EndGetMessages(IAsyncResult asyncResult) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Queue\CloudQueue.cs:line 1858
   at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions.<>c__DisplayClass1`1.<CreateCallback>b__0(IAsyncResult ar) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Util\AsyncExtensions.cs:line 66
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Azure.WebJobs.Host.Storage.Queue.StorageQueue.<GetMessagesAsyncCore>d__16.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Azure.WebJobs.Host.Queues.Listeners.QueueListener.<ExecuteAsync>d__25.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Azure.WebJobs.Host.Timers.TaskSeriesTimer.<RunAsync>d__14.MoveNext()

Host.json settings for queue trigger:

"queues": {
    "maxPollingInterval": 10000, // 10 seconds between polls at lowest polling frequency
    "visibilityTimeout" : "00:00:30", //Default 0	The time interval between retries when processing of a message fails.
        "batchSize": 1, // default was 16. Initially, this was set to 1 to limit parallel execution
        "maxDequeueCount": 5,
        "newBatchThreshold": 0 // Default was: 8 (BatchSize/2)
  },

@ThomasArdal - are you using the v1 runtime as well?

asadiq avatar Apr 30 '20 05:04 asadiq

I'm running on the v2 runtime and none of my functions are long-running.

ThomasArdal avatar Apr 30 '20 05:04 ThomasArdal

Hello. We also have this issue even though the error code is different and it is appear intermittently but not sure how to reproduce it

Singleton lock renewal failed for blob 'xxx/host' with error code 503: ServerBusy.

albilaga avatar Jun 03 '20 10:06 albilaga

I see it every day too

azurefunctions sdkVersion: 3.0.13901.0

Lybecker avatar Jun 24 '20 08:06 Lybecker

Happening on v3 for me too. I have given up and just put an ignore on those errors. Seem to work fine even though the errors are there.

ThomasArdal avatar Jun 24 '20 08:06 ThomasArdal

I have a v3 webjob with only a TimerTrigger function. I am facing the same issue in my job as well:

It stopped with following error: [07/07/2020 23:32:34 > 9c5c6e: INFO] fail: Host.Singleton[0] [07/07/2020 23:32:34 > 9c5c6e: INFO] Singleton lock renewal failed for blob '479b75654df72369bbb792ae03d8c8bb/{_projectname_}.Functions.Run' with error code 306. The last successful renewal completed at 2020-07-07T23:32:07.741Z (27023 milliseconds ago) with a duration of 39 milliseconds. The lease period was 15000 milliseconds. [07/07/2020 23:32:35 > 9c5c6e: ERR ] Unhandled exception. Microsoft.WindowsAzure.Storage.StorageException: The operation was canceled. [07/07/2020 23:32:35 > 9c5c6e: ERR ] ---> System.OperationCanceledException: The operation was canceled. [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Threading.CancellationToken.ThrowOperationCanceledException() [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Threading.CancellationToken.ThrowIfCancellationRequested() [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.FixedSizeReader.ReadPacketAsync(Stream transport, AsyncProtocolRequest request) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Security.SslStream.ThrowIfExceptional() [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Security.SslStream.InternalEndProcessAuthentication(LazyAsyncResult lazyResult) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Security.SslStream.EndProcessAuthentication(IAsyncResult result) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Security.SslStream.EndAuthenticateAsClient(IAsyncResult asyncResult) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Security.SslStream.<>c.<AuthenticateAsClientAsync>b__65_1(IAsyncResult iar) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Threading.Tasks.TaskFactory1.FromAsyncCoreLogic(IAsyncResult iar, Func2 endFunction, Action1 endAction, Task1 promise, Boolean requiresSynchronization) [07/07/2020 23:32:35 > 9c5c6e: ERR ] --- End of stack trace from previous location where exception was thrown --- [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Http.ConnectHelper.EstablishSslConnectionAsyncCore(Stream stream, SslClientAuthenticationOptions sslOptions, CancellationToken cancellationToken) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Http.DiagnosticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.ExecuteAsyncInternal[T](RESTCommand1 cmd, IRetryPolicy policy, OperationContext operationContext, CancellationToken token) [07/07/2020 23:32:35 > 9c5c6e: ERR ] --- End of inner exception stack trace --- [07/07/2020 23:32:35 > 9c5c6e: ERR ] at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.ExecuteAsyncInternal[T](RESTCommand1 cmd, IRetryPolicy policy, OperationContext operationContext, CancellationToken token) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at Microsoft.Azure.WebJobs.Host.StorageBaseDistributedLockManager.SingletonLockHandle.RenewAsync(ILogger logger, CancellationToken cancellationToken) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host.Storage\Singleton\BlobLeaseDistributedLockManager.cs:line 380 [07/07/2020 23:32:35 > 9c5c6e: ERR ] at Microsoft.Azure.WebJobs.Host.SingletonManager.RenewLeaseCommand.ExecuteAsync(CancellationToken cancellationToken) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Singleton\SingletonManager.cs:line 336 [07/07/2020 23:32:35 > 9c5c6e: ERR ] at Microsoft.Azure.WebJobs.Host.Timers.TaskSeriesTimer.RunAsync(CancellationToken cancellationToken) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Timers\TaskSeriesTimer.cs:line 147 [07/07/2020 23:32:35 > 9c5c6e: ERR ] at Microsoft.Azure.WebJobs.Host.Timers.WebJobsExceptionHandler.<>c__DisplayClass3_0.<OnUnhandledExceptionAsync>b__0() in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Timers\WebJobsExceptionHandler.cs:line 54 [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Threading.ThreadHelper.ThreadStart_Context(Object state) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) [07/07/2020 23:32:35 > 9c5c6e: ERR ] --- End of stack trace from previous location where exception was thrown --- [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) [07/07/2020 23:32:35 > 9c5c6e: ERR ] at System.Threading.ThreadHelper.ThreadStart() [07/07/2020 23:32:35 > 9c5c6e: SYS INFO] Status changed to Failed [07/07/2020 23:32:35 > 9c5c6e: SYS ERR ] Job failed due to exit code -532462766 `

abhishek-msft avatar Jul 08 '20 07:07 abhishek-msft

Please see this topic https://github.com/Azure/azure-functions-host/issues/1864

atomhearth avatar Jul 27 '20 11:07 atomhearth