Botbuilder-dotnet: Transient Unauthorized error every several hours

[zhalu]

Github issues should be used for bugs and feature requests. Use Stack Overflow for general "how-to" questions.

Version

4.2.0

Describe the bug

Every several hours, our Bot (built for Microsoft Teams) meet transient Unauthorized exception below. It just happens once every time (if we have only one instance in Azure App Service), and will disappear after next retry. Sometimes the error occurs when sending a message, sometimes it happens when sending a card, and sometimes it happens when getting conversation members, it's totally random.

Microsoft.Bot.Schema.ErrorResponseException: Operation returned an invalid status code 'Unauthorized'
at Microsoft.Bot.Connector.Conversations.d__10.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Connector.ConversationsExtensions.d__17.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.BotFrameworkAdapter.d__15.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.TurnContext.<>c__DisplayClass22_0.<g__SendActivitiesThroughAdapter|1>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.TurnContext.d__21.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.TurnContext.d__20.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.WindowsAzure.XLivesite.StgBot.FrontEnd.Dialogs.BaseWaterfallDialog.d__12`1.MoveNext() in D:\gitroot\Storage\XInfrastructure\src\XLivesite\StgBot\StgBotFrontEnd\Dialogs\BaseWaterfallDialog.cs:line 80
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.WindowsAzure.XLivesite.StgBot.FrontEnd.Dialogs.ActivityIdInfoDialog.d__9.MoveNext() in D:\gitroot\Storage\XInfrastructure\src\XLivesite\StgBot\StgBotFrontEnd\Dialogs\ActivityIdInfoDialog.cs:line 73
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.Dialogs.WaterfallDialog.d__11.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.Dialogs.WaterfallDialog.d__12.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.Dialogs.WaterfallDialog.d__7.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.Dialogs.DialogContext.d__15.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.Dialogs.ComponentDialog.d__10.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.Dialogs.DialogContext.d__15.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.WindowsAzure.XLivesite.StgBot.FrontEnd.StgBot.d__13.MoveNext() in D:\gitroot\Storage\XInfrastructure\src\XLivesite\StgBot\StgBotFrontEnd\StgBot.cs:line 192
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.ShowTypingMiddleware.d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.MiddlewareSet.d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Bot.Builder.BotAdapter.d__13.MoveNext()

To Reproduce

Steps to reproduce the behavior:

1. Just wait several hours;
2. Talk to the Bot, and the error will happen;
3. If we talk to the Bot again immediately, the error won't happen again.

Expected behavior

No such errors any more.

Screenshots

Additional context

Our Bot is built for Microsoft Teams channel, and it's published to Azure App Service as an ASP.NET Core App.

[bug]

[thomasmartinsen-zz]

I experience this as well in other channels (Skype etc.). I have blamed the App Plan so far - I'm currently running on very small instances that are not hot. When the bot tries to contact the Web App it simply needs to wake up and that takes some time.

[jwiley84]

While this 'wake up' is not unexpected behaviour, receiving that error is. @zhalu, can I get your bot ID please? I'd like to see if there's something going on with your bot beyond the timeout.

[zhalu]

I experience this as well in other channels (Skype etc.). I have blamed the App Plan so far - I'm currently running on very small instances that are not hot. When the bot tries to contact the Web App it simply needs to wake up and that takes some time.

@thomasmartinsen I'm afraid "wake up" isn't my case. Though I'm also running on very small instances, I set "Always On" to true. As a result, the Web App will be on always and don't need to be waked up.

[zhalu]

While this 'wake up' is not unexpected behaviour, receiving that error is. @zhalu, can I get your bot ID please? I'd like to see if there's something going on with your bot beyond the timeout.

@jwiley84 My Bot Id is 306724f2-5354-4161-95c0-caefdcd089da, thanks a lot for the prompt follow up!

[zhalu]

Hi, is there any investigation progress for this bug? We're keeping seeing this every day.

[cleemullins]

This is likley a dupe of #1251. It almost certainly has the same root cause - bugs in the token refresh logic. This work is expected to land this iteration (4.3) and should be on the daily build server next week.

From that issue:

The likely cause here is a token caching bug in the v4 SDK. Last release, in the V3 C# SDK, we moved away from our custom code and over to a turnkey solution offered by the AAD team. So far, that seems to have been working quite well, and we're comfortable with the solution. As a nice side effect of this work, performance under very high load is also quite a bit better.

The work is under way right now in the v4 C# SDK and is planned in the 4.3 release in mid Feb. I suspect it'll start showing up on the daily build server next week. @carlosscastro is driving this work.

I'm tagging this Issue as such, and we'll track it as part of Carlos's work.

[cleemullins]

Fixed in 4.2.1.

https://github.com/Microsoft/botbuilder-dotnet/releases/tag/4.2.1