search

microsoft / botframework-solutions

Welcome to the Bot Framework Solutions repository which is the home for a set of templates and solutions to help build advanced conversational experiences using Azure Bot Service and Bot Framework. Microsoft Bot Framework is a comprehensive framework for building enterprise-grade conversational AI experiences.
https://aka.ms/bfsolutionsdocs
MIT License
1.05k stars 530 forks source link

Intermittent Virtual Assistant error #1047

Closed angie4u closed 5 years ago

angie4u commented 5 years ago

Project

Name: Intermittent Virtual Assistant error

Language: C#

Description

An unknown error has intermittently happened for VA project. My customer who test this solution a lot have these error sometimes and they would like to know what the problem is.

To Reproduce

It happens Intermittently, so it is hard to reproduce. I asked the customer and they replied it happens around once in ten times

Expected behavior

Should not happen this error

Screenshots

image

Error Message

{ "channelId": "emulator", "conversation": { "id": "1e0a8bc0-4c90-11e9-99c9-b1909a54d900|livechat" }, "from": { "id": "108", "name": "Bot", "role": "bot" }, "id": "e8aaf3b0-4c90-11e9-a072-49751b73f512", "localTimestamp": "2019-03-22T19:54:47+09:00", "locale": "", "recipient": { "id": "5cf9d7e4-c17b-450e-bca1-da72b0cf9f37", "role": "user" }, "replyToId": "e7e5a7e0-4c90-11e9-a072-49751b73f512", "serviceUrl": "https://d1bf43d6.ngrok.io", "text": "Virtual Assistant Error: An error occurred while sending the request. | at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)\r\n at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)\r\n at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)\r\n at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)\r\n at System.Net.Http.DiagnosticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)\r\n at Microsoft.Rest.RetryAfterDelegatingHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)\r\n at Microsoft.Rest.RetryDelegatingHandler.<>c__DisplayClass11_0.<<SendAsync>b__1>d.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n at Microsoft.Rest.RetryDelegatingHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)\r\n at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)\r\n at Microsoft.Bot.Connector.Conversations.ReplyToActivityWithHttpMessagesAsync(String conversationId, String activityId, Activity activity, Dictionary`2 customHeaders, CancellationToken cancellationToken)\r\n at Microsoft.Bot.Connector.ConversationsExtensions.ReplyToActivityAsync(IConversations operations, String conversationId, String activityId, Activity activity, CancellationToken cancellationToken)\r\n at Microsoft.Bot.Builder.BotFrameworkAdapter.SendActivitiesAsync(ITurnContext turnContext, Activity[] activities, CancellationToken cancellationToken)\r\n at Microsoft.Bot.Builder.TurnContext.<>c__DisplayClass22_0.<<SendActivitiesAsync>g__SendActivitiesThroughAdapter|1>d.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n at Microsoft.Bot.Builder.TranscriptLoggerMiddleware.<OnTurnAsync>b__4_0(ITurnContext ctx, List`1 activities, Func`1 nextSend)\r\n at Microsoft.Bot.Solutions.TelemetryLoggerMiddleware.<OnTurnAsync>b__13_0(ITurnContext ctx, List`1 activities, Func`1 nextSend) in D:\\work\\ms\\git\\vow\\VirtualAssistant\\solutions\\Virtual-Assistant\\src\\csharp\\Microsoft.Bot.Solutions\\Middleware\\Telemetry\\TelemetryLoggerMiddleware.cs:line 98\r\n at Microsoft.Bot.Builder.TurnContext.SendActivityAsync(IActivity activity, CancellationToken cancellationToken)\r\n at Microsoft.Bot.Solutions.Skills.SkillDialog.ForwardToSkill(DialogContext dc, Activity activity) in D:\\work\\ms\\git\\vow\\VirtualAssistant\\solutions\\Virtual-Assistant\\src\\csharp\\Microsoft.Bot.Solutions\\Skills\\SkillDialog.cs:line 252\r\n at Microsoft.Bot.Solutions.Skills.SkillDialog.ForwardToSkill(DialogContext dc, Activity activity) in D:\\work\\ms\\git\\vow\\VirtualAssistant\\solutions\\Virtual-Assistant\\src\\csharp\\Microsoft.Bot.Solutions\\Skills\\SkillDialog.cs:line 296\r\n at Microsoft.Bot.Solutions.Skills.SkillDialog.ContinueDialogAsync(DialogContext dc, CancellationToken cancellationToken) in D:\\work\\ms\\git\\vow\\VirtualAssistant\\solutions\\Virtual-Assistant\\src\\csharp\\Microsoft.Bot.Solutions\\Skills\\SkillDialog.cs:line 122\r\n at Microsoft.Bot.Builder.Dialogs.DialogContext.ContinueDialogAsync(CancellationToken cancellationToken)\r\n at Microsoft.Bot.Builder.Dialogs.ComponentDialog.ContinueDialogAsync(DialogContext outerDc, CancellationToken cancellationToken)\r\n at Microsoft.Bot.Builder.Dialogs.DialogContext.ContinueDialogAsync(CancellationToken cancellationToken)\r\n at Microsoft.Bot.Solutions.RouterDialog.OnContinueDialogAsync(DialogContext innerDc, CancellationToken cancellationToken) in D:\\work\\ms\\git\\vow\\VirtualAssistant\\solutions\\Virtual-Assistant\\src\\csharp\\Microsoft.Bot.Solutions\\Dialogs\\RouterDialog.cs:line 49\r\n at Microsoft.Bot.Builder.Dialogs.ComponentDialog.ContinueDialogAsync(DialogContext outerDc, CancellationToken cancellationToken)\r\n at Microsoft.Bot.Builder.Dialogs.DialogContext.ContinueDialogAsync(CancellationToken cancellationToken)\r\n at VirtualAssistant.VirtualAssistant.OnTurnAsync(ITurnContext turnContext, CancellationToken cancellationToken) in D:\\work\\ms\\git\\vow\\VirtualAssistant\\solutions\\Virtual-Assistant\\src\\csharp\\assistant\\VirtualAssistant.cs:line 68\r\n at Microsoft.Bot.Builder.AutoSaveStateMiddleware.OnTurnAsync(ITurnContext turnContext, NextDelegate next, CancellationToken cancellationToken)\r\n at Microsoft.Bot.Solutions.Middleware.EventDebuggerMiddleware.OnTurnAsync(ITurnContext turnContext, NextDelegate next, CancellationToken cancellationToken) in D:\\work\\ms\\git\\vow\\VirtualAssistant\\solutions\\Virtual-Assistant\\src\\csharp\\Microsoft.Bot.Solutions\\Middleware\\EventDebuggerMiddleware.cs:line 110\r\n at Microsoft.Bot.Solutions.Middleware.SetLocaleMiddleware.OnTurnAsync(ITurnContext context, NextDelegate next, CancellationToken cancellationToken) in D:\\work\\ms\\git\\vow\\VirtualAssistant\\solutions\\Virtual-Assistant\\src\\csharp\\Microsoft.Bot.Solutions\\Middleware\\SetLocaleMiddleware.cs:line 32\r\n at Microsoft.Bot.Builder.ShowTypingMiddleware.OnTurnAsync(ITurnContext turnContext, NextDelegate next, CancellationToken cancellationToken)\r\n at Microsoft.Bot.Builder.TranscriptLoggerMiddleware.OnTurnAsync(ITurnContext turnContext, NextDelegate nextTurn, CancellationToken cancellationToken)\r\n at Microsoft.Bot.Solutions.TelemetryLoggerMiddleware.OnTurnAsync(ITurnContext context, NextDelegate nextTurn, CancellationToken cancellationToken) in D:\\work\\ms\\git\\vow\\VirtualAssistant\\solutions\\Virtual-Assistant\\src\\csharp\\Microsoft.Bot.Solutions\\Middleware\\Telemetry\\TelemetryLoggerMiddleware.cs:line 138\r\n at Microsoft.Bot.Builder.MiddlewareSet.ReceiveActivityWithStatusAsync(ITurnContext turnContext, BotCallbackHandler callback, CancellationToken cancellationToken)\r\n at Microsoft.Bot.Builder.BotAdapter.RunPipelineAsync(ITurnContext turnContext, BotCallbackHandler callback, CancellationToken cancellationToken)", "timestamp": "2019-03-22T10:54:47.403Z", "type": "trace" }
darrenj commented 5 years ago

Thanks for raising, this is an issue I've seen intermittently too - we'll take a more detailed look.

darrenj commented 5 years ago

If your able to share Activity.Id for the activity that triggers this that would help us diagnose, Thanks.

angie4u commented 5 years ago

Thank you @darrenj for the reply! Hello @jongyeop2 Could you share Activity.Id for this kind of error?

lzc850612 commented 5 years ago

What version of the release is the customer using? This was a SDK bug back in 4.2 but should have been resolved in newer versions. The latest release should not have this issue any more.

darrenj commented 5 years ago

I can repro in 4.3.1

darrenj commented 5 years ago

Angie - have you ever seen this error outside of emulator usage, we are starting to think it might be ngrok related.

jongyeop2 commented 5 years ago

[LGE] We saw this issue only when using emulator. We don't know if this error is also occurred outside of emulator usage.

CoHealer commented 5 years ago

@mdrichardson, can you please help determine if this is related to ngrok?

mdrichardson commented 5 years ago

@angie4u I've been trying to replicate this without success. I'm using VA 4.4.38 debugging this both locally and deployed on Azure. I also upgraded ngrok to the latest available. However, I've been testing with random messages and trying to go through a few different routes/skills.

What path did you/your customer take to get to the error in your attached image? What did they type to get there? That might help me narrow this down and reproduce.

mdrichardson commented 5 years ago

@angie4u @darrenj I'm leaning fairly heavily towards this being an ngrok issue. I was able to replicate this error pretty consistently by downloading NetLimiter and setting a 15KB/s In/Out bandwidth limit on ngrok. That's the only time I got this error to show up consistently (or at all, really).

I attempted to reproduce this in "Test in Web Chat" by hitting F12 > Network and setting a similar bandwidth limit and was unable to reproduce the error. It would instead give a normal timeout error instead of the "Sorry, it looks like something went wrong".

I also ran the bot locally, but used an Azure Service Bus Relay to test it via "Test in Web Chat". I used NetLimiter to add a bandwidth limit to my local Service Bus Relay and would occasionally get similar timeout errors but never the "Sorry, it looks like something went wrong." error.

Additionally, the server logs in Kudu show this error message when this happens (full stack trace below):

[Error] Microsoft.AspNetCore.Server.Kestrel: Connection id "0HLM9OJ8VDJG3", Request id "0HLM9OJ8VDJG3:00000009": An unhandled exception was thrown by the application.

System.Net.Http.HttpRequestException: An error occurred while sending the request. ---> System.IO.IOException: The server returned an invalid or unrecognized response.

In ngrok, I see something like this in the logs:

image

So, I think what's happening is more or less:

  1. Bot sends request to ngrok
  2. Request times out
  3. ngrok reports nothing (or something invalid)
  4. Bot/Asp.Net server can't interpret this and doesn't respond to whatever ngrok sends back
  5. Bot sends error

I'm far from an expert at troubleshooting these things, so I won't definitively say it's ngrok, but I'm definitely leaning that way.

Stack trace:

2019-04-25 21:55:28.733 +00:00 [Information] Microsoft.Bot.Builder.Integration.IAdapterIntegration: Sending activity.  ReplyToId: d2a24c60-67a4-11e9-83cc-b7503afc354a
2019-04-25 21:55:28.826 +00:00 [Error] Microsoft.AspNetCore.Server.Kestrel: Connection id "0HLM9OJ8VDJG3", Request id "0HLM9OJ8VDJG3:00000009": An unhandled exception was thrown by the application.
System.Net.Http.HttpRequestException: An error occurred while sending the request. ---> System.IO.IOException: The server returned an invalid or unrecognized response.
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   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.TranscriptLoggerMiddleware.<>c__DisplayClass3_0.<<OnTurnAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Bot.Builder.Solutions.Telemetry.TelemetryLoggerMiddleware.<OnTurnAsync>b__6_0(ITurnContext ctx, List`1 activities, Func`1 nextSend)
   at Microsoft.Bot.Builder.TurnContext.SendActivityAsync(IActivity activity, CancellationToken cancellationToken)
   at VirtualAssistant.Startup.<>c__DisplayClass7_1.<<ConfigureServices>b__4>d.MoveNext() in C:\vaDarren\assistant\Startup.cs:line 135
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Bot.Builder.BotAdapter.RunPipelineAsync(ITurnContext turnContext, BotCallbackHandler callback, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.BotFrameworkAdapter.ProcessActivityAsync(ClaimsIdentity identity, Activity activity, BotCallbackHandler callback, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.BotFrameworkAdapter.ProcessActivityAsync(String authHeader, Activity activity, BotCallbackHandler callback, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.Integration.AspNet.Core.Handlers.BotMessageHandler.ProcessMessageRequestAsync(HttpRequest request, IAdapterIntegration adapter, BotCallbackHandler botCallbackHandler, CancellationToken cancellationToken)
   at Microsoft.Bot.Builder.Integration.AspNet.Core.Handlers.BotMessageHandlerBase.HandleAsync(HttpContext httpContext)
   at Microsoft.AspNetCore.Builder.Extensions.MapMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware.Invoke(HttpContext context)
   at Microsoft.Bot.Builder.Integration.ApplicationInsights.Core.TelemetrySaveBodyASPMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.Server.IISIntegration.IISMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
2019-04-25 21:55:28.828 +00:00 [Information] Microsoft.AspNetCore.Hosting.Internal.WebHost: Request finished in 21698.0092ms 500
darrenj commented 5 years ago

Thanks @mdrichardson - awesome investigation. After my own testing last week I'm leaning the same way. Whenever it does happen, immediately sending the same message works and we can't see anything on our cloud service side again pointing towards client/network issues.

We could perhaps explore special handling of this message generating a "network error ocurred" type of more friendly message. Do we have any suggestions beyond ngrok that a customer might choose to try if they run into this more often (different parts of the world may be more suspectible)

mdrichardson commented 5 years ago

@darrenj @angie4u Yes, we do have suggestions beyond ngrok. We have a blog post about how to use Azure Service Bus Relays that got published a couple weeks ago. It takes a bit of setup, but works really well. Personally, I prefer it to ngrok since it keeps everything within Azure.

CoHealer commented 5 years ago

Removing support from the investigation with the recommendation to use Service Bus