First welcome message is delayed for 5 seconds

[compulim]

Version

4.10.0

Describe the bug

The first welcome message coming in is being delayed for 5 seconds. Probably due to recent accessibility fix that would delay message up to 5 seconds if their "reply-to-id" activity was not arrived yet.

Steps to reproduce

1. Go to MockBot2
2. You should see "Hello and welcome!"

Expected behavior

Instead, the "Hello and welcome!" arrive 5 seconds after the Web Socket packet has arrived.

Additional context

[Bug]

[compulim]

The first activity from the bot has a replyToId pointing to a non-existing ID.

The following screenshot is the first activity after Web Socket is connected.

To repro:

• Open https://compulim.github.io/webchat-loader/
• Click "[Public] MockBot 2 (Preview)"
• Open network tab
• Look at the traffic for the transcript

[compulim]

(Ping SDK team to better understand why the bot is replying to a non-existing activity ID.)

[stevengum]

Related to #3236

[compulim]

Talked to @stevengum of SDK team and looks like it is technically impossible to have the replyToId from the first activity removed. I.e. even the first activity is essentially, the first. It is replying to something "earlier than the first activity".

We will use a shorter timeout for the first activity.

[corinagum]

@compulim looks like this one is still causing errors in IcM 203406335

[corinagum]

When updating the playground, I noticed that there is around a 5 second delay for when the typing indicator is shown when sendTypingIndicator is sent to true. Is it related to this change?

[compulim]

Investigate 1

It only affect typing activities. It does not affect message activities.

We are testing against https://microsoft.github.io/BotFramework-WebChat/05.custom-components/b.send-typing-indicator/.

When user type, we receive the echoback activity of typing without replyToId. Let's call this activity 1.

When the bot echo, the bot replied to activity 1. Let's call this activity 2.

The delay is caused by activity 2 not showing up sooner.

We should study why the logic isn't followed:

• Activity 1 doesn't have replyToId and it should be visible in the transcript immediately
• Activity 2 depends on activity 1. Because activity 1 is already on the transcript, it should display immediately as well

[MatthiasGwiozda]

We have this problem with Version 4.10.1:

When showing the chat history to the user and combining this with the reaction buttons, the reaction - buttons and the welcome - messages are delayed by ~5 seconds when reloading the page.

Could be a hint to find the solution for this problem.

[compulim]

Investigations

The problem is, we didn't put "activity of type typing" inside the transcript. Thus, the "typing" activity from the bot will never able to find the activity it is replying to.

But for "message" activities, I tested it with current build and it actually looks good.

I have a prototype working, by "don't skip the typing activity, always put it in transcript".

Before finalizing the solution, I will investigate @MatthiasGwiozda issue a bit furthermore. Thanks @MatthiasGwiozda.

[compulim]

@MatthiasGwiozda I think you might be hitting a different issue. We are only seeing the issue related to typing activity.

When loading chat history, for activities that have replyToId specified, are those referenced activities appears in the chat history too?

In code, that means,

activities.find(x => x.replyToId && activities.every(y => y.id !== x.replyToId))

If you see anything show up, they are "activities that are replying to another activity that does not exist, or did not arrive yet". Activities listed will be delayed as we are waiting for their associated activity to arrive thru the network or until timeout.

In the PR #3554, I am adding a new console warning to help diagnosing activities that are delayed due to their counterpart did not show up on time.

[MatthiasGwiozda]

The bug is not fixed for me with the following components. The delay with 5 seconds still persists:

This is the welcome - Bot :

https://github.com/microsoft/BotBuilder-Samples/tree/main/samples/typescript_nodejs/03.welcome-users/src

and this is the frontend with the newest webchat - version and the webchat/join - event:

<!DOCTYPE html>
<html>

<head>
    <script crossorigin="anonymous" integrity="sha384-VaCCB1kZvCsUv3mrVO7ND25gqCPmUGP9NMOJEveBa1vsLyQw3i4pdOq03UZtMLE8"
        src="https://cdn.botframework.com/botframework-webchat/4.11.0/webchat.js"></script>

    <style>
        html,
        body {
            height: 100%;
        }

        body {
            margin: 0;
        }

        #webchat {
            height: 100%;
            width: 100%;
        }
    </style>
</head>

<body>
    <div id="webchat" role="main"></div>
    <script>
        const store = window.WebChat.createStore({}, ({ dispatch }) => next => action => {
            if (action.type === 'DIRECT_LINE/CONNECT_FULFILLED') {
                dispatch({
                    type: 'WEB_CHAT/SEND_EVENT',
                    payload: {
                        name: 'webchat/join',
                        value: { language: window.navigator.language }
                    }
                });
            }

            return next(action);
        });

        window.WebChat.renderWebChat(
            {
                directLine: window.WebChat.createDirectLine(
                    {
                        // token: 'XXXXX'
                    }
                ),
                userID: 'YOUR_USER_ID',
                username: 'Web Chat User',
                locale: 'en-US',
                store
            },
            document.getElementById('webchat')
        );
    </script>
</body>

</html>

With this 2 components the message is shown after 5 seconds. But when I use the onEvent - handler in the welcome-users-bot, the message is shown faster and the bug seems to be fixed with this backend - code:

constructor() {
        super();

        this.onEvent(async (context, next) => {
            if (context.activity.name === 'webchat/join') {
                await context.sendActivity(
                    `Got \`webchat/join\` event, your language is \`${(context.activity.value || {}).language}\``
                );
            }
            await next();
        })

// (...)
}

My Suggestion is to change the botbuilder-Samples to use the "onEvent - function" because they are currently not working correctly (even when I use the newest Versions of webchat and botbuilder (4.11.0))

[MatthiasGwiozda]

@MatthiasGwiozda I think you might be hitting a different issue. We are only seeing the issue related to typing activity.

When loading chat history, for activities that have replyToId specified, are those referenced activities appears in the chat history too?

In code, that means,

activities.find(x => x.replyToId && activities.every(y => y.id !== x.replyToId))

If you see anything show up, they are "activities that are replying to another activity that does not exist, or did not arrive yet". Activities listed will be delayed as we are waiting for their associated activity to arrive thru the network or until timeout.

In the PR #3554, I am adding a new console warning to help diagnosing activities that are delayed due to their counterpart did not show up on time.

There are replyToId's that doesn't seem to exist. This is the case for the first message where the replyToId seems to be in a different format than the other activity - id'd:

"malformed first message replyToId": AZdTGlUdbui
"not malformed replyToId": F4Mi2hwvvWVJAvq3YuZ19a-o|0000000

Interestingly the problem that we had with the reaction - buttons is solved now after the welcome - message is sent without a delay.
This means for me that the reaction -button - problem is in fact related with the delayed welcome - message.

[corinagum]

reopening for investigation. @compulim could you take a look?

[arman-g]

I have the same problem, is there any fix for this?
In my case Posted activity, assigned ID 5Zm7lkFt0YgBeqOUIrs6RB-f|0000001
but replyTo is 5Zm7lkFt0YgBeqOUIrs6RB-f|0000000
ReplyTo has always "0000000", is it hard coded?

Update*
Timeout happens only with the latest version of WebChat v4.11.0
I noticed that when webSocket is set to false of DirectLine object it does not have this issue.

[eyadon]

I believe I am having this problem too.
When I connect to the bot in Chrome, mobile or desktop, it comes up right away.
When I connect to the bot in a webview in my Xamarin app, there is a clear 5 second delay between the "Connecting..." indicator and when the first message appears.

[compulim]

Update on the IcM ticket 203406335: that ticket is resolved by the SDK. So it's probably unrelated to this issue.

So we still need to investigate/fix in Web Chat.

[compulim]

@eyadon "Connecting..." is different, this indicator is based on whether the Web Socket is connected or not. It is not based on any activities received. If it take 5 seconds for "Connecting..." to go away, the Web Socket take 5 seconds to connect.

If the delay is caused by waiting for an activity, you should see a warning in the console. If you see any, can you copy it here?

[compulim]

@arman-g this ID is from Azure Bot Services. Web Chat has no control over the value or its content. Thus, Web Chat won't parse it or do any comparisons over them. We just treat it as a string and assume it's non-sequential like a random GUID.

[compulim]

@MatthiasGwiozda I talked to the SDK team and they said this is a by-design issue: the first activity ID is in "malformed" format. And they won't take it out.

So in Web Chat, if the transcript is empty, we will not delay any activities with Reply-To-ID set. In other words, we will not delay the first activity coming in, regardless it has Reply-To-ID or not.

And right now, activities sent by the user do not set Reply-To-ID, so we won't delay showing up these activities too.

Looks like your problem is fixed (after your edit on Nov 22). If you continue to see the problem, please copy the console warning regarding the delay to us.

Thanks!

[compulim]

Found the issue.

This is because of a race condition:

• After created a conversation
• User send an activity (or Web Chat programmatically sending out an activity)
• At the same time, the bot also send another activity, with reply to ID of a bogus activity

The timeout occurs if the user's message was send before the bot message was received.

Originally, we allow the bot's activity to show up even they point to a bogus activity, if that message was the very first activity in the transcript.

Because the user's activity was already in the transcript, the relaxation was not granted. Thus, the bot's activity is subject to "reply to ID" and a timeout.