Azure-webjobs-sdk: Webjob crashing with error : : Microsoft.WindowsAzure.Storage.StorageException: The client could not finish the operation within specified timeout.

Created on 18 Oct 2017 · 11Comments · Source: Azure/azure-webjobs-sdk

Please provide a succinct description of the issue.

We are using Azure Web Job with Azure Storage Queue and we are having a timeout exception inside the framework reading logs.

Provide the steps required to reproduce the problem

You will found in an attachement a sample reproducing the issue. At first the sample fill 5 queue with 5000 messages and then read them. At some point the application crashes with 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.,
--- End of inner exception stack trace ---,
at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.EndExecuteAsyncT in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Executor\Executor.cs:line 50,
at Microsoft.WindowsAzure.Storage.Blob.CloudBlobContainer.EndCreate(IAsyncResult asyncResult) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlobContainer.cs:line 133,
at Microsoft.WindowsAzure.Storage.Blob.CloudBlobContainer.EndCreateIfNotExists(IAsyncResult asyncResult) in c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlobContainer.cs:line 329,
at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions.<>c__DisplayClass1`1.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.Loggers.BlobFunctionOutputLogger.d__3.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.Executors.FunctionExecutor.<>c__DisplayClass13_0.<b__0>d.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.Executors.FunctionExecutor.d__13.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.Executors.FunctionExecutor.d__10.MoveNext(),_

2af365-8828.applicationLog.csv.zip
CrashTest.zip

Expected behavior

Runing without any error.

Actual behavior

Crash several time during just one run.

Related information

In the attachement you will find the source code for the sample and an Excel file containing the last run console log for the WebJob.

To run the sample you juste have to setup the access key to your souscription.

Provide any related information

Package version
Links to source

Source

Nicofrms

Most helpful comment

WebJobs SDK saves log blobs to “azure-jobs-host-output” container for each execution of the method. Your scenario uses lot of bandwidth and run into timeouts from the SDK trying to save log blobs.
The issue can be resolved by disabling dashboard logging in the code:

            var config = new JobHostConfiguration();
            config.DashboardConnectionString = null;

alrod on 23 Feb 2018

👍3 👀1

All 11 comments

I run CrashTest on my webiste/storage account and did not get Exceptions:
output_log.txt

You can try to increase ServiceClient.DefaultRequestOptions.ServerTimeout using CustomQueueProcessorFactory

https://github.com/Azure/azure-webjobs-sdk-samples/tree/master/BasicSamples/MiscOperations
https://github.com/Azure/azure-webjobs-sdk-samples/blob/master/BasicSamples/MiscOperations/CustomQueueProcessorFactory.cs

alrod on 19 Oct 2017

Hello,

I have re run the sample adding this line of code for each of the five queue :
ffe854-7100.applicationLog.log

queue.ServiceClient.DefaultRequestOptions.ServerTimeout = TimeSpan.FromSeconds(100);

With 30 seconds, 60 and 100 and I still have the issue. See file in attachement.

You can contact me internaly I can give you access to the web app and ressource group.

Thanks

Nicofrms on 17 Nov 2017

            var config = new JobHostConfiguration();
            config.DashboardConnectionString = null;

alrod on 23 Feb 2018

👍3 👀1

I ran into the exact same problem today. My WebJobs are running in an App Service instance, and this particular job has been processing 10.000 queue messages daily for at least a month with absolutely no issues.

I have now implemented the work-around described by alrod above. The remaining 7000 messages in the queue were processed in less than 2 minutes.

I would like to have the Dashboard logging activated again, so please investigate the issue. I would assume there is an issue with some storage accounts in data center West Europe?

Thanks,

Eigil

eigil-rosager on 28 Feb 2018

I can confirm that @alrod 's suggestion to disable dashboard logging looks to have solved WebJob crashes for me as well. My exception stack was different (including for others searching for the fix):

[06/08/2018 12:16:19 > 5c8429: ERR ] Unhandled Exception: Microsoft.WindowsAzure.Storage.StorageException: The operation was canceled. ---> System.OperationCanceledException: The operation was canceled.
[06/08/2018 12:16:19 > 5c8429: ERR ]    at System.Net.Http.HttpClient.HandleFinishSendAsyncError(Exception e, CancellationTokenSource cts)
[06/08/2018 12:16:19 > 5c8429: ERR ]    at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
[06/08/2018 12:16:19 > 5c8429: ERR ]    at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.ExecuteAsyncInternal[T](RESTCommand`1 cmd, IRetryPolicy policy, OperationContext operationContext, CancellationToken token)
[06/08/2018 12:16:19 > 5c8429: ERR ]    --- End of inner exception stack trace ---
[06/08/2018 12:16:19 > 5c8429: ERR ]    at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.ExecuteAsyncInternal[T](RESTCommand`1 cmd, IRetryPolicy policy, OperationContext operationContext, CancellationToken token)
[06/08/2018 12:16:19 > 5c8429: ERR ]    at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.UploadFromStreamAsyncHelper(Stream source, Nullable`1 length, AccessCondition accessCondition, BlobRequestOptions options, OperationContext operationContext, IProgress`1 progressHandler, CancellationToken cancellationToken)
[06/08/2018 12:16:19 > 5c8429: ERR ]    at Microsoft.Azure.WebJobs.Host.Loggers.UpdateOutputLogCommand.UpdateOutputBlob(CancellationToken cancellationToken, Boolean flushAndClose) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Loggers\UpdateOutputLogCommand.cs:line 161
[06/08/2018 12:16:19 > 5c8429: ERR ]    at Microsoft.Azure.WebJobs.Host.Loggers.UpdateOutputLogCommand.TryExecuteAsync(CancellationToken cancellationToken) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Loggers\UpdateOutputLogCommand.cs:line 80
[06/08/2018 12:16:19 > 5c8429: ERR ]    at Microsoft.Azure.WebJobs.Host.Timers.RecurrentTaskSeriesCommand.ExecuteAsync(CancellationToken cancellationToken) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Timers\RecurrentTaskSeriesCommand.cs:line 22
[06/08/2018 12:16:19 > 5c8429: 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 149
[06/08/2018 12:16:19 > 5c8429: 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 58
[06/08/2018 12:16:19 > 5c8429: ERR ]    at System.Threading.Thread.ThreadMain_ThreadStart()
[06/08/2018 12:16:19 > 5c8429: ERR ]    at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
[06/08/2018 12:16:19 > 5c8429: ERR ]    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
[06/08/2018 12:16:19 > 5c8429: ERR ] --- End of stack trace from previous location where exception was thrown ---
[06/08/2018 12:16:19 > 5c8429: ERR ]    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
[06/08/2018 12:16:19 > 5c8429: ERR ]    at System.Threading.ThreadHelper.ThreadStart()
[06/08/2018 12:16:19 > 5c8429: SYS ERR ] Job failed due to exit code -532462766
[06/08/2018 12:16:19 > 5c8429: SYS INFO] Process went down, waiting for 0 seconds

I have other jobs running ~1,000 operations/hour that did not have a problem with logging. The job that was crashing was running ~3,500 operations/hour and pretty consistently crashed every ~20-40 minutes.

Are there any guidelines on what is the threshold for a web job to be considered "high throughput" and not a good candidate for logging? Are there any plans for an alternate solution or a fix for "high throughput" web jobs?

codecadwallader on 8 Jun 2018

@alrod I don't believe this issue should be closed. This is a workaround, not a fix. Please consider re-opening to track this issue as it is a real problem. Disabling the dashboard is not acceptable.

oising on 30 Oct 2018

Any update on this problem? I would also like to be able to run with dashboarding on.

erikmourits on 7 Feb 2019

In my experience, it can be a workaround to deploy Webjob and Storage in the same region.

Mikako-ff on 18 Jun 2019

FWIW I do have web job and storage in the same region and that didn't help. Also though, I think dashboard logging is generally frowned upon now and is being deprecated out of the newer SDK (e.g. v3).

codecadwallader on 18 Jun 2019

I'm sorry for writing uncertain information.
(In my environment, the same error sometimes occurs on all storage accesses, including logging. only if deploying to other region.)

Mikako-ff on 19 Jun 2019

I am seeing below error in job logs

[07/25/2019 12:02:08 > ec7f29: SYS ERR ] Job failed due to exit code -532462766

got below from event logs

    <Event>
        <System>
            <Provider Name=".NET Runtime"/>
            <EventID>1026</EventID>
            <Level>1</Level>
            <Task>0</Task>
            <Keywords>Keywords</Keywords>
            <TimeCreated SystemTime="2019-07-25T11:58:16Z"/>
            <EventRecordID>1090731953</EventRecordID>
            <Channel>Application</Channel>
            <Computer>RD281878C8454F</Computer>
            <Security/>
        </System>
        <EventData>
            <Data>Application: MyWebJob.exe
Framework Version: v4.0.30319
Description: The process was terminated due to an unhandled exception.
Exception Info: System.InvalidOperationException
   at System.Net.HttpWebRequest.BeginGetResponse(System.AsyncCallback, System.Object)
   at Microsoft.WindowsAzure.Storage.Core.Util.APMWithTimeout.Begin(System.Func`3&lt;System.AsyncCallback,System.Object,System.IAsyncResult&gt;, System.AsyncCallback, System.Object, System.TimeSpan)
   at Microsoft.WindowsAzure.Storage.Core.Util.APMWithTimeout.RunWithTimeout(System.Func`3&lt;System.AsyncCallback,System.Object,System.IAsyncResult&gt;, System.AsyncCallback, System.Threading.TimerCallback, System.Object, System.TimeSpan)
   at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.BeginGetResponse[[System.__Canon, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089]](Microsoft.WindowsAzure.Storage.Core.Executor.ExecutionState`1&lt;System.__Canon&gt;)

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.Queue.CloudQueue.EndDeleteMessage(System.IAsyncResult)
   at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions+&lt;&gt;c__DisplayClass4.&lt;CreateCallbackVoid&gt;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.Queues.QueueProcessor+&lt;DeleteMessageAsync&gt;d__32.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.Queues.QueueProcessor+&lt;CompleteProcessingMessageAsync&gt;d__29.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.Queues.Listeners.QueueListener+&lt;ProcessMessageAsync&gt;d__31.MoveNext()
   at Microsoft.Azure.WebJobs.Host.Timers.WebJobsExceptionHandler+&lt;&gt;c__DisplayClass3_0.&lt;OnUnhandledExceptionAsync&gt;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()

</Data>
        </EventData>
    </Event>