Botbuilder-dotnet: 'Unauthorized error on start of conversation - Randomly v4.1.5

[sammydeprez]

Version

• bot builder v4.1.5
• .net core 2.2

Describe the bug

We get randomly 'Unauthorized' errors on the start of the conversation.

See error below, what is quite strange because:

• It doesn't happen often
• And the error is send from the bot, so the DirectLine API already communicated with the bot, but the bot cant send anything back to the DirectLine. (this is something we assume, but hard to debug)

We are still on MemoryStorage, but don't think this has anything todo with it.

To Reproduce

Can't reproduce, very randomly

Additional context

Microsoft.Bot.Schema.ErrorResponseException: Operation returned an invalid status code 'Unauthorized'
   at Microsoft.Bot.Connector.Conversations.ReplyToActivityWithHttpMessagesAsync(String conversationId, String activityId, Activity activity, Dictionary`2 customHeaders, CancellationToken cancellationToken)
   at Microsoft.Bot.Connector.ConversationsExtensions.ReplyToActivityAsync(IConversations operations, String conversationId, String activityId, Activity activity, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.BotFrameworkAdapter.SendActivitiesAsync(ITurnContext turnContext, Activity[] activities, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.TurnContext.<>c__DisplayClass22_0.<<SendActivitiesAsync>g__SendActivitiesThroughAdapter|1>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Bot.Builder.TurnContext.SendActivityAsync(IActivity activity, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.TurnContext.SendActivityAsync(String textReplyToSend, String speak, String inputHint, CancellationToken cancellationToken)
   at Louise.Chatbot.DialogSteps.GreetingDialogSteps.GreetUserAsync(WaterfallStepContext stepContext, CancellationToken cancellationToken) in C:\Users\.....\GreetingDialogSteps.cs:line 26
   at Microsoft.Bot.Builder.Dialogs.WaterfallDialog.OnStepAsync(WaterfallStepContext stepContext, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.Dialogs.WaterfallDialog.RunStepAsync(DialogContext dc, Int32 index, DialogReason reason, Object result, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.Dialogs.WaterfallDialog.BeginDialogAsync(DialogContext dc, Object options, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.Dialogs.DialogContext.BeginDialogAsync(String dialogId, Object options, CancellationToken cancellationToken)
   at Louise.Chatbot.Louise.OnTurnAsync(ITurnContext turnContext, CancellationToken cancellationToken) in C:\Users\.....\Louise.cs:line 154
   at Microsoft.Bot.Builder.MiddlewareSet.ReceiveActivityWithStatusAsync(ITurnContext turnContext, BotCallbackHandler callback, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.BotAdapter.RunPipelineAsync(ITurnContext turnContext, BotCallbackHandler callback, CancellationToken cancellationToken)

[bug]

[sammydeprez]

No idea if this exactly the same as Bug: #1246
Since there it comes during the conversation also

[jwiley84]

Hi Sammy! I believe they're related and am looking into it. Can I get your bot's app ID?

[sammydeprez]

Hi Sammy! I believe they're related and am looking into it. Can I get your bot's app ID?

@jwiley84 BotId: 879eb492-1ad9-4033-84d8-8aabfbbe91cc
Thanks for checking.

[sammydeprez]

@jwiley84 : We did an update to v4.2 and we still get the error

Microsoft.Bot.Schema.ErrorResponseException: Operation returned an invalid status code 'Unauthorized' at Microsoft.Bot.Connector.Conversations.ReplyToActivityWithHttpMessagesAsync(String conversationId, String activityId, Activity activity, Dictionary2 customHeaders, CancellationToken cancellationToken) at Microsoft.Bot.Connector.ConversationsExtensions.ReplyToActivityAsync(IConversations operations, String conversationId, String activityId, Activity activity, CancellationToken cancellationToken) at Microsoft.Bot.Builder.BotFrameworkAdapter.SendActivitiesAsync(ITurnContext turnContext, Activity[] activities, CancellationToken cancellationToken) at Microsoft.Bot.Builder.TurnContext.<>c__DisplayClass22_0.<<SendActivitiesAsync>g__SendActivitiesThroughAdapter|1>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Bot.Builder.TurnContext.SendActivityAsync(IActivity activity, CancellationToken cancellationToken) at Microsoft.Bot.Builder.TurnContext.SendActivityAsync(String textReplyToSend, String speak, String inputHint, CancellationToken cancellationToken) at Louise.Chatbot.DialogSteps.GreetingDialogSteps.GreetUserAsync(WaterfallStepContext stepContext, CancellationToken cancellationToken) in C:\....\.....Chatbot\DialogSteps\GreetingDialogSteps.cs:line 26 at Microsoft.Bot.Builder.Dialogs.WaterfallDialog.OnStepAsync(WaterfallStepContext stepContext, CancellationToken cancellationToken) at Microsoft.Bot.Builder.Dialogs.WaterfallDialog.RunStepAsync(DialogContext dc, Int32 index, DialogReason reason, Object result, CancellationToken cancellationToken) at Microsoft.Bot.Builder.Dialogs.WaterfallDialog.BeginDialogAsync(DialogContext dc, Object options, CancellationToken cancellationToken) at Microsoft.Bot.Builder.Dialogs.DialogContext.BeginDialogAsync(String dialogId, Object options, CancellationToken cancellationToken) at Louise.Chatbot.Louise.OnTurnAsync(ITurnContext turnContext, CancellationToken cancellationToken) in C:\.....\.....Chatbot\Louise.cs:line 153 at Microsoft.Bot.Builder.MiddlewareSet.ReceiveActivityWithStatusAsync(ITurnContext turnContext, BotCallbackHandler callback, CancellationToken cancellationToken) at Microsoft.Bot.Builder.BotAdapter.RunPipelineAsync(ITurnContext turnContext, BotCallbackHandler callback, CancellationToken cancellationToken)

[torynfarr]

We've been encountering this issue ever since switching to v4 of the SDK. (Currently running the same as the original poster: Bot Builder v4.2.0 and ASP .Net Core 2.2)

Similar Error Details:

Microsoft.Bot.Schema.ErrorResponseException: Operation returned an invalid status code 'Unauthorized' at Microsoft.Bot.Connector.Conversations.ReplyToActivityWithHttpMessagesAsync(String conversationId, String activityId, Activity activity, Dictionary'2 customHeaders, CancellationToken cancellationToken) at Microsoft.Bot.Connector.ConversationsExtensions.ReplyToActivityAsync(IConversations operations, String conversationId, String activityId, Activity activity, CancellationToken cancellationToken) at Microsoft.Bot.Builder.BotFrameworkAdapter.SendActivitiesAsync(ITurnContext turnContext, Activity[] activities, CancellationToken cancellationToken) at Microsoft.Bot.Builder.TurnContext.<>c__DisplayClass22_0.<<SendActivitiesAsync>g__SendActivitiesThroughAdapter|1>d.MoveNext()--- End of stack trace from previous location where exception was thrown --- at Microsoft.Bot.Builder.TurnContext.SendActivityAsync(IActivity activity, CancellationToken cancellationToken)

I've opened a Microsoft Premier Support ticket for this one (#118111525002586).

With our chat bot, it seems to happen after the bot hasn't been accessed for awhile... so it's difficult to reproduce on-demand. The issue occurs both in web chat and in Microsoft Teams, so it doesn't appear to be channel specific.

We have our chat bot proactively greet the user when they invoke the bot (in web chat), so the error occurs immediately when the web chat control loads and the bot (and user) joins the conversation. In Teams, however, we don't proactively greet the user. There, the user's utterance is matched to an intent via LUIS and the bot's code branches off appropriately. The moment the bot tries to send a response, the error occurs.

I was recently pointed to this blog post regarding periodic token refresh: https://blog.botframework.com/2017/11/02/optimizing-latency-bot-framework/

I'm going to try to implement that and see if it helps resolve the issue.

[drub0y]

So the token caching implementation in MicrosoftAppCredentials is pretty rough (starts here). It's also a point of high contention/serialization due to locks on single instance variables (i.e. locking on TokenTaskCache). The whole implementation should be revisited, reimplemented and optimized IMHO.

[sammydeprez]

@torynfarr : what reply did you get on your support ticket?

[torynfarr]

@sammydeprez After trying a ton of things and providing every log file we could, the current status is that the "product group" is indeed able to reproduce it on their end with their own bots. No ETA on a fix or anything, but they've confirmed that it's not specific to our bot or how our bot is written.

[zhalu]

I'm also encountering the same issue every day on my Bot, here is my issue link: https://github.com/Microsoft/botbuilder-dotnet/issues/1246

[cleemullins]

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]

@drub0y, per your "Should be revisited" comment, we all agree. The V3 PR that integrated the ADAL library is found here.

There are a few other PRs around this. See #69 and #73.

The MSAL and ADAL libraries are new to us (MSAL is not, last I checked, GA yet), so we introduced this in the V3 SDK first, and let it bake there for a cycle before moving it forward.

[drub0y]

@cleemullins I've revised the V4 implementation to remove locks and fix a couple other issues I came across. I've tested it locally and it's working fine, but, at least code wise, it could still benefit from one more pass to clean up/add some comments since the implementation is non-trivial. Another thing is there's only three simple unit tests around this class (all still passing) which don't really do a great job covering scenarios which should probably make everyone uncomfortable. 😕

Would you be interested in a PR if I invest more time in this or do you just want to let this ride until you guys make the shift to ADAL?

[cleemullins]

This is has been fixed (in theory!) in 4.2.1.
https://github.com/Microsoft/botbuilder-dotnet/releases/tag/4.2.1