Azure-webjobs-sdk: Unhandled StorageException: (400) Bad Request thrown from SDK logging code

[dustinwilcock]

Occasionally, while running multiple instances in Azure App Services (not in development), our continuous WebJob terminates irregularly. The following is from Application Logging:

Unhandled Exception: Microsoft.WindowsAzure.Storage.StorageException: The remote server returned an error: (400) Bad Request. ---> System.Net.WebException: The remote server returned an error: (400) Bad Request.
   at Microsoft.WindowsAzure.Storage.Shared.Protocol.HttpResponseParsers.ProcessExpectedStatusCodeNoException[T](HttpStatusCode expectedStatusCode, HttpStatusCode actualStatusCode, T retVal, StorageCommandBase`1 cmd, Exception ex)
   at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.<>c__DisplayClass42.<PutBlobImpl>b__41(RESTCommand`1 cmd, HttpWebResponse resp, Exception ex, OperationContext ctx)
   at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.EndGetResponse[T](IAsyncResult getResponseResult)
   --- End of inner exception stack trace ---
   at Microsoft.WindowsAzure.Storage.Core.Util.StorageAsyncResult`1.End()
   at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadFromStream(IAsyncResult asyncResult)
   at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadFromByteArray(IAsyncResult asyncResult)
   at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadText(IAsyncResult asyncResult)
   at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions.<>c__DisplayClass4.<CreateCallbackVoid>b__3(IAsyncResult ar)
--- 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.UpdateOutputLogCommand.<UpdateOutputBlob>d__10.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.Loggers.UpdateOutputLogCommand.<TryExecuteAsync>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.Timers.RecurrentTaskSeriesCommand.<ExecuteAsync>d__0.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__d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.WebJobs.Host.Timers.BackgroundExceptionDispatcher.<>c__DisplayClass1.<Throw>b__0()
   at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()

The above is with 1.1.2. It also occurs with 2.0.0-beta2. The call stack looks slightly different:

Unhandled Exception: Microsoft.WindowsAzure.Storage.StorageException: The remote server returned an error: (400) Bad Request. ---> System.Net.WebException: The remote server returned an error: (400) Bad Request.
   at Microsoft.WindowsAzure.Storage.Shared.Protocol.HttpResponseParsers.ProcessExpectedStatusCodeNoException[T](HttpStatusCode expectedStatusCode, HttpStatusCode actualStatusCode, T retVal, StorageCommandBase`1 cmd, Exception ex)
   at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.<>c__DisplayClass42.<PutBlobImpl>b__41(RESTCommand`1 cmd, HttpWebResponse resp, Exception ex, OperationContext ctx)
   at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.EndGetResponse[T](IAsyncResult getResponseResult)
   --- End of inner exception stack trace ---
   at Microsoft.WindowsAzure.Storage.Core.Util.StorageAsyncResult`1.End()
   at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadFromStream(IAsyncResult asyncResult)
   at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadFromByteArray(IAsyncResult asyncResult)
   at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadText(IAsyncResult asyncResult)
   at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions.<>c__DisplayClass4.<CreateCallbackVoid>b__3(IAsyncResult ar)
--- 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.UpdateOutputLogCommand.<UpdateOutputBlob>d__10.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.Loggers.UpdateOutputLogCommand.<TryExecuteAsync>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.Timers.RecurrentTaskSeriesCommand.<ExecuteAsync>d__0.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__d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.WebJobs.Host.Timers.WebJobsExceptionHandler.<>c__DisplayClass7.<OnUnhandledExceptionAsync>b__6()
   at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()

The worst part, is that it seems that our WebJob process sometimes doesn't (most the time, it does) get restarted by the Azure platform after it terminates irregularly. We've had times where all our instances eventually get into this state, and processing comes to a stand-still. We have to Stop and re-Start the WebJob in the Azure portal for processing to resume.

[dustinwilcock]

It's seems to be related to the use of ServiceBusTrigger's, and WindowsAzure.Storage package version. I cannot reproduce the problem referencing version 6.2.0, but can reproduce it readily with 7.2.1. Also, can't repro it in a WebJob referencing 7.2.1 (and 2.0.0-beta2) with only EventHubTrigger's (no ServiceBusTriggers).

[markwsanders]

I know it may seem unrelated, but anytime I have received an unexplainable StorageException I spend hours trying to figure out the problem. I go down several different rabbit holes. In every case, for me, it ends up being an issue with the blob's metadata. Either assigning invalid data (such as null) to a blob's metadata or an invalid metadata name. It tends to be intermittent for me because in the situations where it happens I am processing dynamic data coming from another system that sends over information in a format I didn't yet account for. Are you working with blob metadata in your application?

[dustinwilcock]

Interesting insight. While we don't employ blob triggers or blob outputs in webjob functions, we do access blob data and properties (ETag, ContentEncoding, etc.) in service bus trigger functions (queues).

[markwsanders]

I saw Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadFromStream and thought maybe you were trying to upload/update a blob, which is what sparked my memory about past StorageExceptions when dealing with uploading blobs. Hope you are able to figure out the issue. Good luck!

[dustinwilcock]

We're only reading blobs not writing them. That, and the fact that we don't see our own code on the call stack, made me wonder if it were SDK code writing to blob as part of webjob logging...

[christopheranderson]

@MikeStall - my theory is that this is related to issues we see with high throughput in our blob logging. could you confirm that that's likely the case?

@dustinwilcock - If you disable the dashboard logging, do you see these messages?

@paulbatum / @davidebbo - we need someone to improve the error handling in the case that storage is overloaded for logging.

[mathewc]

The call stack Microsoft.Azure.WebJobs.Host.Loggers.UpdateOutputLogCommand is coming from our internal logging code which logs any output from your function from TextWriter/TraceWriter to blobs, which drives our Dashboard logging experience.

@dustinwilcock this logging codepath doesn't vary between trigger types (ServiceBus/EventHub) so I'd be surprised if that was related. Can you help us create a repro for this? Is your function under heavy load when this occurs?

[dustinwilcock]

Thanks. It may be related to application logging. We turned that off when we noticed another issue that we suspected to be related to logging (but it's not).

We'll have several instances of the webjob running, when all of them hang and don't process occasionally EXACTLY on the top of the hour, which is when application logging to blob turns over to a new set of blobs/files, thus suspect. In that case, webjob processes all still show in Process Explorer, but they're doing nothing.
But it happened again over the weekend. Had to Stop and Start webjob to kick start it. Only the ServiceBus trigger (queues and topics) job. The other job that uses EventHub triggers does not have this problem.

We haven't noticed this issue (webjob process gone on certain instances in Process Explorer, don't start back up) since application logging has been turned off. But it would be harder to recognize as exactly the same issue (by call stack) because application logging is turned off!

[paulbatum]

If you're impacted by this issue we recommend trying the new App Insights integration we have for functions and webjobs. This will become the default monitoring experience in the coming months as its a much more reliable and feature rich solution. For more info see here:
https://github.com/Azure/Azure-Functions/wiki/App-Insights-(Preview)

[hansmbakker]

I always get a 400 bad request on cloudTable.CreateIfNotExists() after upgrading WindowsAzure.Storage version 8.1.4 to 8.2.0.

When reverting back to 8.1.4 the code worked again.

I was using it like this:

CloudStorageAccount storageAccount = CloudStorageAccount.Parse(
                connectionString);

_tableClient = storageAccount.CreateCloudTableClient();

_table = _tableClient.GetTableReference("someTableName");
_table.CreateIfNotExists();

[paulbatum]

@wind-rider our recommendation is that you stick with storage sdk 7.x while on version 2.x of webjobs. The upcoming version 3.x of webjobs will target storage sdk 8.x

[hanikhurma]

@wind-rider change the _table to "sometablename"

[awahnteh]

@paulbatum: how does one force the version of WIndowsAzure Storage SDK in Azure functions?
I have tried adding a dependentAssembly binding redirect in the web.config file for my AzureFunctions blade to no avail. Still get the same error:
<bindingRedirect oldVersion="0.0.0.0-8.1.4.0" newVersion="7.2.1.0" />

Did no one test this before releaseing v8.x into the wild?

[atrauzzi]

Encountering this as well, not sure what to do. Getting a 400, running latest local emulator, I can't downgrade to 7.x because some of my libraries are bound to 8.x so that they can work with .net core.

[paulbatum]

@awahnteh If storage v8.x is being loaded by your function app, then one of your dependencies must be pulling it in. Since functions does not have any support for binding redirects, you need to downgrade your dependencies as appropriate to get back to 7.2.1.

@atrauzzi Unfortunately we don't have solution for that yet, see the (lengthy) https://github.com/Azure/azure-webjobs-sdk-script/issues/992

[fabiocav]

@atrauzzi if you don't mind, please provide (in a separate issue) the details of your setup. This will help us make sure we clearly understand what you're running into (problem with a conflicting transient dependency) and whether it would be addressed by some work we have planned. We might also have some recommendations on potential workarounds.

[Piekop]

Hi all,
I know this has been a while, but we're experiencing the same issues with our webjobs.
Host dll is version 2.2.0.0.
The servicebustriggers are stalling while others keep un running correctly.
We don't have any storage operations in our own code, but the SDK is logging operations to the blobstorage.
More specific we're experiencing a 400 (bad request MD5mistmatch)
Any help is much appreciated.

Microsoft.WindowsAzure.Storage.StorageException : The remote server returned an error: (400) Bad Request. ---> System.Net.WebException : The remote server returned an error: (400) Bad Request.,
" at Microsoft.WindowsAzure.Storage.Shared.Protocol.HttpResponseParsers.ProcessExpectedStatusCodeNoExceptionT at c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlockBlob.cs : 3131",
at Microsoft.WindowsAzure.Storage.Core.Executor.Executor.EndGetResponseT at c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Executor\Executor.cs : 299 ,
End of inner exception,
at Microsoft.WindowsAzure.Storage.Core.Util.StorageAsyncResult`1.End() at c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Util\StorageAsyncResult.cs : 77,
at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadFromStream(IAsyncResult asyncResult) at c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlockBlob.cs : 844,
at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadFromByteArray(IAsyncResult asyncResult) at c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlockBlob.cs : 1323,
at Microsoft.WindowsAzure.Storage.Blob.CloudBlockBlob.EndUploadText(IAsyncResult asyncResult) at c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Blob\CloudBlockBlob.cs : 1482,
at Microsoft.WindowsAzure.Storage.Core.Util.AsyncExtensions.<>c__DisplayClass7.b__5(IAsyncResult ar) at c:\Program Files (x86)\Jenkins\workspace\release_dotnet_master\Lib\ClassLibraryCommon\Core\Util\AsyncExtensions.cs : 120,
" at async Microsoft.Azure.WebJobs.Host.Loggers.UpdateOutputLogCommand.UpdateOutputBlob(CancellationToken cancellationToken,Boolean flushAndClose)",
" at async Microsoft.Azure.WebJobs.Host.Loggers.UpdateOutputLogCommand.SaveAndCloseAsync(FunctionInstanceLogEntry item,CancellationToken cancellationToken)",
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(??),
" at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryExecuteAsync(IFunctionInstance functionInstance,CancellationToken cancellationToken)",
Additional Details:,
UserSpecifiedMd5: 1B2M2Y8AsgTpgAmY7PhCfg==,
ServerCalculatedMd5: uaYUEDgc/d/MnqA6p6KV0A==,
,