botframework-sdk icon indicating copy to clipboard operation
botframework-sdk copied to clipboard

BotFramework ReactWebChat With DirectLineAppServiceExtension getting repeated welcome message on specific time interval

Open pravinambekar opened this issue 2 years ago • 21 comments

Version

What package version of the SDK are you using. Bot Builder V4 SDK .Net Core 3.1

Describe the bug

I have C# SDK based azure bot developed and deployed on azure, this bot is using Language(Custom Question Answering) service for answering users questions. The front end part is a SPFX React WebChat which is a webpart of another sharepoint site and the communication with Bot service is happening over DirectLineApp Service Extension (Web Socket).

The bot is working fine in Emulator or in Test WebChat(In portal) but i am facing issue about repeated welcome message when running it from spfx react webchat.

image

The problem i analyzed so far is that the event OnMembersAddedAsync have the comparison logic for member added and turncontext receipent id where the values are different always. Which are something like: MemID- dl_ab955807-50ea-4dd8-8bd7-ef6598e0c050 ---> direct line guid generated while requesting token ReceipentID- xxxx-bot-t-xxxx@kT5LB7DBjMs ---> Bot handle id@Site id

Which are never same for any request.

 foreach (var member in turnContext.Activity.MembersAdded)
            {
                if (member.Id != turnContext.Activity.Recipient.Id)
                {
                    var welcomeCard = CreateAdaptiveCardAttachment();
                    var response = MessageFactory.Attachment(welcomeCard);
                    await turnContext.SendActivityAsync(response, cancellationToken);
                  }
            }

To Reproduce

Steps to reproduce the behavior:

  1. Create Azure Bot and customize code with Bot framework sdk
  2. Enable Direct Line App Service Extension
  3. Create SPFX react Web Chat application that will first fetch for token on componentDidMount() react event hook
  4. Load Bot interface on React Render() method on button click
  5. Welcome screen will appear for the first time
  6. Welcome screen will reappear approximately after 5 to 7 min (Screen shot attached herewith)

Expected behavior

Once the bot is successfully hosted and running on azure, the bot should respond to user request properly at first it when client side UI launch the app or bot window it should fetch the token then it should greet user with the welcome message and for next subsequent communication it should answer users queries. (In my case the bot responding well to user queries but welcome screen re appears multiple times)

Screenshots

165280318-a678deee-57fa-4c71-8a6c-949cd0ff85d6

Additional context

Fetch token method in react webchat

private async fetchToken() {  
    var myToken ='<<--Secret Key-->>';  
      const res = await fetch('https://fxxx-test-xxx.azurewebsites.net/api/GetLRToken', 
    { method: 'GET',
      headers: {'accept': 'application/json'}  
    });
    var { token } = await res.json();
    console.log(token);  
    this.setState({  
        directLine: await createDirectLineAppServiceExtension({
        domain: 'https://cxx-bot-t-xxx.azurewebsites.net/.bot/v3/directline',
        token,
      }),
    });  
    this.state.directLine.postActivity({  
      from: { id: "serId", name: "USER_NAME" },  
      name: "requestWelcomeDialog",  
      type: "event",  
      value: "token"  
    }).subscribe(  
      id => console.log(`Posted activity, assigned ID ${id}`),  
      error => console.log(`Error posting activity ${error}`)  
    );  
  }

Tracking Status

Dotnet SDK TODO

  • [ ] PR
  • [ ] Merged

Javascript SDK TODO

  • [ ] PR
  • [ ] Merged

Python SDK TODO

  • [ ] PR
  • [ ] Merged

Java SDK TODO

  • [ ] PR
  • [ ] Merged

Samples TODO

  • [ ] PR
  • [ ] Merged

Docs TODO

  • [ ] PR
  • [ ] Merged

Tools TODO

  • [ ] PR
  • [ ] Merged

pravinambekar avatar Apr 26 '22 10:04 pravinambekar

HI @pravinambekar Does this reproduce with WebChat (not Emulator or TiWC) hosted outside of a Sharepoint webpart?

dmvtech avatar Apr 27 '22 17:04 dmvtech

HI @pravinambekar Does this reproduce with WebChat (not Emulator or TiWC) hosted outside of a Sharepoint webpart?

@dmvtech Hello Dana, No, this has never occured with web chat, in fact before implementing this in ReactWebChat SPFX i have hosted bot with simple web chat having DirectLine App service Extension and never seen this issue before.

  window.WebChat.renderWebChat(
          {
            directLine: await window.WebChat.createDirectLineAppServiceExtension({
              domain: 'https://xxx-xxx-xxx.azurewebsites.net/.bot/v3/directline',
              token,
              styleSet,
              styleOptions: avatarOptions
            })
          },
          document.getElementById('webchat')
        );

But i have debug client side tsx while observing re-appearing of welcome message and at any point i never found that some action is being triggered from spfx (that was little surprising) Also the events or hooks where token is requested or Render method is called never re-initiated during this process, hence confusion is more about how to trace .

Moreover i think the Member added async method gets called twice first time for event and second time for conversation as you can see :

 protected override async Task OnMembersAddedAsync(IList<ChannelAccount> membersAdded, ITurnContext<IConversationUpdateActivity> turnContext, CancellationToken cancellationToken)
        {
            await SendWelcomeMessageAsync(turnContext, cancellationToken);
          }
          
      private static async Task SendWelcomeMessageAsync(ITurnContext turnContext, CancellationToken cancellationToken)
        {
            foreach (var item in turnContext.Activity.MembersAdded)
            {
                **await turnContext.SendActivityAsync("MemID-" + item.Id + "-ReceipentID-" + turnContext.Activity.Recipient.Id);**
                if (item.Id != turnContext.Activity.Recipient.Id)
                {
                    var welcomeCard = CreateAdaptiveCardAttachment();
                    var response = MessageFactory.Attachment(welcomeCard);
                    await turnContext.SendActivityAsync(response, cancellationToken);

                }
            }
        }

The console log message : await turnContext.SendActivityAsync("MemID-" + item.Id + "-ReceipentID-" + turnContext.Activity.Recipient.Id); print twice the detail about Member and Receipent id

image

And both time the member id is different f.x the first time it is bot handleid@code and second time DL GUI ID which is generated while getting token from the service.

pravinambekar avatar Apr 28 '22 04:04 pravinambekar

@dmvtech Hello Dana, Some additional finding during investigation about directLineStreaming.js. I have observed that the piece of code from directLineStreaming.js gets hit after every 4 to 5 minutes The function call is : connectWithRetryAsync and the condition that frequently gets hit is :

 case 8:
                res = _context10.sent;
                console.warn("Retrying connection ".concat(res));

                if (!(60000 < Date.now() - start)) {
                  _context10.next = 13;
                  break;
                }

from the function :

  key: "connectWithRetryAsync",
    value: function () {
      var _connectWithRetryAsync = (0, _asyncToGenerator2["default"])( /*#__PURE__*/_regenerator["default"].mark(function _callee10() {
        var _this7 = this;

        var numRetries, start, res;
        return _regenerator["default"].wrap(function _callee10$(_context10) {
          while (1) {
            switch (_context10.prev = _context10.next) {
              case 0:
                numRetries = MAX_RETRY_COUNT;

              case 1:
                if (!(numRetries > 0)) {
                  _context10.next = 23;
                  break;
                }

                numRetries--;
                start = Date.now();
                _context10.prev = 4;
                this.connectionStatus$.next(_directLine.ConnectionStatus.Connecting);
                _context10.next = 8;
                return this.connectAsync();

              case 8:
                res = _context10.sent;
                console.warn("Retrying connection ".concat(res));

                if (!(60000 < Date.now() - start)) {
                  _context10.next = 13;
                  break;
                }

                // reset the retry counter and retry immediately
                // if the connection lasted for more than a minute
                numRetries = MAX_RETRY_COUNT;
                return _context10.abrupt("continue", 1);

              case 13:
                _context10.next = 19;
                break;

              case 15:
                _context10.prev = 15;
                _context10.t0 = _context10["catch"](4);
                console.error("Failed to connect ".concat(_context10.t0));
                throw _context10.t0;

              case 19:
                _context10.next = 21;
                return new Promise(function (r) {
                  return setTimeout(r, _this7.getRetryDelay());
                });

              case 21:
                _context10.next = 1;
                break;

              case 23:
              case "end":
                return _context10.stop();
            }
          }
        }, _callee10, this, [[4, 15]]);
      }));

      function connectWithRetryAsync() {
        return _connectWithRetryAsync.apply(this, arguments);
      }

      return connectWithRetryAsync;
    }() // Returns the delay duration in milliseconds

Does this have anything related to the issue i am facing because, only after this the Network interruption error occur and Welcome message re-appears

pravinambekar avatar Apr 28 '22 08:04 pravinambekar

Hello @dmvtech , did you found my previous comment of any use ? I am following up on this thread as i didn't found anything that could help to resolve this issue, moreover i think its React SPFX part where the issue lies .

pravinambekar avatar May 02 '22 03:05 pravinambekar

hi @pravinambekar Sorry for the delay. Thank you for the additional information. I am going over that and will get back to you soon.

dmvtech avatar May 05 '22 00:05 dmvtech

have observed that the piece of code from directLineStreaming.js

Where is directLineStreaming.js coming from? What library?

Are you able to share a reproduction webpart that would allow us to reproduce and debug?

dmvtech avatar May 05 '22 21:05 dmvtech

Hello @dmvtech ,

the directLineStreaming.js file comes from //node_modules/botframework-directlinejs/lib/directLineStreaming.js Also please find attached webpart and related package json Web Part source.zip

pravinambekar avatar May 06 '22 05:05 pravinambekar

Hello Dana, @dmvtech Did you find my comment useful ?

pravinambekar avatar May 11 '22 05:05 pravinambekar

Hello Dana, @dmvtech Did you find my comment useful ?

Hello @dmvtech @ramfattah , I am really not sure if the issue i reported is something i terribly did wrong (in the way of implementation) or it indeed has some serious problem in term of feature available with DL ASE and React WebChat and DirectLine Streaming js. What surprises me is not just GitHub but even on other community forum (and exclusive Microsoft Support) no positive response has seen, which makes impression either it really doesn't worth attention or its just some silly mistake as normally happens before getting actual solution. I know limitations of social platform and community forum but sometime not getting solution really makes terrible impression. Hope this messages gets your attention and at least i expect response (whatever it is)

pravinambekar avatar May 17 '22 04:05 pravinambekar

Hello Dana, @dmvtech Did you find my comment useful ?

Hello @dmvtech , Any update on this ?

pravinambekar avatar May 23 '22 13:05 pravinambekar

Hi @pravinambekar

I am now able to reproduce (it was not trivial getting it set up correctly). Investigation so far has yet to yield any root causes. I am currently finding the correct resources to help narrow that down.

dmvtech avatar May 23 '22 23:05 dmvtech

Hello @dmvtech ,

Have you had any chance for further investigating this, have you got any resource to find root cause ? I am just concerned as it is taking bit more time than expected

pravinambekar avatar Jun 06 '22 09:06 pravinambekar

Hi @pravinambekar I am unable to determine the root cause. I have involved @compulim to see if he can identify the culprit.

dmvtech avatar Jun 08 '22 17:06 dmvtech

@compulim - Could you please help with identifying the root cause of this issue? Thanks!

msomanathan avatar Jul 14 '22 17:07 msomanathan

I am seeing this repro BOTH on SharePoint Framework (SPFx workbench.aspx) and on a plain HTML page outside of SPFx.

image

In the screenshot, I loaded Web Chat 4.15.2 on SPFx (left) and on a plain HTML page (right). Both are loaded at the same time, connected to the same bot via Direct Line ASE protocol. And then I idled both browsers for a couple of minutes.

I am observing both of them reconnect almost at the same time, around 4 minutes.

Looks like this is a protocol or service-side issue as both of them reconnect at the same time.

compulim avatar Aug 08 '22 19:08 compulim

The following is a video showing both SharePoint (left) and plain HTML page (right) having the reconnect prompt at the same time at about 7 minutes mark.

https://user-images.githubusercontent.com/1622400/183509491-8eba35a4-0d51-4713-bcc0-f5921c089018.mp4

Leaving both browsers on extended time.

image

compulim avatar Aug 08 '22 20:08 compulim

Someone need to investigate the Web Socket connection and see why it is disconnected, following this "road" of components:

  1. Web Chat
  2. DirectLineJS (ASE)
  3. Bot Framework Streaming Extensions (running on browser)
  4. DL ASE extension on Azure Web Apps
  5. Web Socket on Azure Web Apps
  6. Bot Framework Streaming Extensions (running on service)
  7. Bot SDK
  8. Bot code

What we know so far is that this is not related to Web Chat, and this is not related to bot code:

  • Not Web Chat because Web Chat do not have any network code, we can't do disconnection
  • Not bot code because it can repro on customer's bot and my sample bot

So must be something between 2 and 7 inclusively.

compulim avatar Aug 08 '22 21:08 compulim

I have validated #4 locally so it points to the possibility of idle timeout of websocket in Azure WebApps

ckkashyap avatar Aug 10 '22 18:08 ckkashyap

Some documentation points to a 230 second timeout for websockets

  1. https://docs.microsoft.com/en-us/answers/questions/758823/httptrigger-response-timeout.html
  2. https://docs.microsoft.com/en-us/answers/questions/649953/app-service-websocket-timeout.html

ckkashyap avatar Aug 24 '22 21:08 ckkashyap

One possible workaround in this situation is to update the client code to send periodic "event" activities. The sample code below shows how one could get a handle to the DirectLine Object and send a nop evet periodically - every 3 minutes.

  var dl = await window.WebChat.createDirectLineAppServiceExtension({ domain: 'https://server/v3/directline', token });

  setInterval(() => { dl.postActivity({type: "event"}).subscribe() }, 180000); // send event every 3 minutes

  window.WebChat.renderWebChat( { directLine: dl }, document.getElementById('webchat'));

ckkashyap avatar Sep 02 '22 16:09 ckkashyap

One possible workaround in this situation is to update the client code to send periodic "event" activities. The sample code below shows how one could get a handle to the DirectLine Object and send a nop evet periodically - every 3 minutes.

  var dl = await window.WebChat.createDirectLineAppServiceExtension({ domain: 'https://server/v3/directline', token });

  setInterval(() => { dl.postActivity({type: "event"}).subscribe() }, 180000); // send event every 3 minutes

  window.WebChat.renderWebChat( { directLine: dl }, document.getElementById('webchat'));

postActivity does not accept{type: "event"}as a paramenter it gives following error,

Argument of type '{ type: "event"; }' is not assignable to parameter of type 'Activity'. Type '{ type: "event"; }' is missing the following properties from type 'EventActivity': name, value, fromts(2345)

Instead of that I only used an EventActivity object let activity: EventActivity = { type: 'event', name: 'eventName', value: null, from: null }; and that worked

kedar-andharikar avatar Sep 14 '22 08:09 kedar-andharikar

Closing this as a work around has been provided. Please reopen if this needs more attention.

johnataylor avatar Oct 05 '22 18:10 johnataylor