Proactive Message Delay in Client

[cxbuilders]

This is a bit of an overlapping issue between Sdk / Composer / Client, however posting it here.

I have developed an handoff integration with Genesys that is built around a websocket that calls ContinueConversationAsync when a new message arrives from the agent :

private async Task SendActivity(string eventName, string text = null, object data = null)
{
    await DialogContext.Context.Adapter.ContinueConversationAsync(_claimsIdentity, _conversationReference, new BotCallbackHandler(async (turnContext, cancellationToken) =>
    {
        turnContext.Activity.Type = ActivityTypes.Event;
        turnContext.Activity.Name = eventName;
        turnContext.Activity.Text = text;
        turnContext.Activity.Value = data;
        await _callbackHandler(turnContext, cancellationToken);
    }), default);
}

This is then picked up in Composer and send to the user:

The speed at which the message arrives at the client (emulator in this scenario) is within a second. However before it is actually displayed another 6 seconds pass.

So in the screenshot below the yellow marked "ola" arrives almost instantaneously but 6 seconds pass before it is displayed in the chat itself.

What is causing this?

[srinaath]

@cxbuilders Do you experience the same when using the integrated webchat experience in Composer?

[v-kydela]

@cxbuilders - I wonder if this might be related to the rendering issue I reported here: microsoft/BotFramework-Emulator#2262

I can see that they're not the same issue, because you're saying the activity appears in the log at the right time and doesn't appear in the transcript until later, and in my issue you can see that the messages appear in the log and the transcript at the same time. However, this definitely still looks like a client issue. Try it in Web Chat and other channels just to be sure.

@srinaath - I see that you assigned me. What would you like me to do about this bug?

[cxbuilders]

@v-kydela I don't think that's related as the delay does not occur when the bot is responding to a user activity. On the webchat it's the same, if it would only be emulator it would not be a problem.

[v-kydela]

@cxbuilders - Do you have a minimal example that can help us reproduce this problem? Does this only occur when you're using your Genesys handoff integration, or can you reproduce it with an ordinary proactive message?

[cxbuilders]

@v-kydela This happens with any proactive message, I have seen this happening with notification style messages from external systems, but that was never an issue. Direct chat between agent and user is ofcourse.

I don't have a minimal example, however I think a Custom Action with a loop in it that sends every 10 seconds or so an event that is picked up by Composer would do, as the emulator allows you to clearly see the delay between incoming and displaying

[cxbuilders]

@srinaath Yes the integrated webchat does the exact same thing, steady 6/7 sec delay

[v-kydela]

@cxbuilders - Have you determined that the problem is specific to Composer? Have you tried this with a non-Composer bot? Have you tried sending messages with Postman?

[cxbuilders]

@v-kydela I created a minimal example bot that has a custom component that loops and sends an event activity every 10 seconds. You can see that when the activity arrives in the Emulator log, it still takes a good 5 / 6 seconds for it to show up.

http://cxbuilders.com/temp/ProActiveDelay.zip

[v-kydela]

@cxbuilders - It looks like you've shared a Composer project. I tried starting your project in Composer and it failed to build. What version of Composer would you like me to try with?

[cxbuilders]

@v-kydela This is the latest 1.4.0 Just tested it again and runs without issues (except the one this issue is about :) )

[v-kydela]

@cxbuilders - I can reproduce your problem now. I had a look at your custom action code:

private async Task SendActivity(DialogContext dc)
{
    _claimsIdentity = dc.Context.TurnState.Get<ClaimsIdentity>("BotIdentity");
    _callbackHandler = dc.Context.TurnState.Get<BotCallbackHandler>("Microsoft.Bot.Builder.BotCallbackHandler");
    _conversationReference = dc.Context.Activity.GetConversationReference();
    int _counter = 1;

    while (true)
    {
        await dc.Context.Adapter.ContinueConversationAsync(_claimsIdentity, _conversationReference, new BotCallbackHandler(async (turnContext, cancellationToken) =>
        {
            turnContext.Activity.Type = ActivityTypes.Event;
            turnContext.Activity.Name = "Notification";
            turnContext.Activity.Text = "notification #" + _counter.ToString();
            await _callbackHandler(turnContext, cancellationToken);
        }), default);

        await Task.Delay(10000);
        _counter++;
    }            
}

This looks very unusual to me. Can you perhaps explain why you're doing this this way? Where did you get the idea to get the ClaimsIdentity and the BotCallbackHandler from the turn state? Why are you sending a reply by calling a saved callback handler instead of just using the turn context? Is there a sample that does things like that?

I know it's generally a bad idea to modify the incoming activity like that, but I have no idea if that's related to the problem.

[cxbuilders]

@v-kydela The Custom Action runs a-synchronic, so to mimic incoming agent messages, which are unrelated to incoming user messages and therefore there is no turn present.

This is the same principal as a pro active message. This is the same code @Stevenic used in his proactive teams message sample in microsoft/BotFramework-Composer#4093

[v-kydela]

@cxbuilders - I can reproduce this with a non-Composer bot, and so I've determined that this is not Composer-related. I can reproduce the problem in Web Chat and Emulator (which uses Web Chat), but not in Teams. This is most likely to be a Web Chat bug.

@Kaiqb
@compulim
@corinagum

I've transferred this bug to the Web Chat repro and unassigned myself. Can someone have a look at it? Here's a code sample that I think is a bit simpler than Steve's:

internal static Task TestProactiveMessagesAsync(ITurnContext turnContext, CancellationToken cancellationToken)
{
    var adapter = turnContext.Adapter;
    var identity = turnContext.TurnState.Get<ClaimsIdentity>(BotAdapter.BotIdentityKey);
    var conversationReference = turnContext.Activity.GetConversationReference();

    Task.Run(
        async () =>
        {
            while (true)
            {
                await adapter.ContinueConversationAsync(
                    identity,
                    conversationReference,
                    new BotCallbackHandler(async (turnContext, cancellationToken) =>
                    {
                        await turnContext.TrySendActivityAsync(DateTime.Now.ToString(), cancellationToken: cancellationToken);
                    }),
                    default);

                await Task.Delay(10000);
            }
        }, cancellationToken);

    return Task.CompletedTask;
}

I'm using DateTime.Now so that you can run Web Chat alongside an online clock with seconds, and you can observe that the messages show up about 5 seconds later than they were sent. If you use a Web Chat client that lets you see the Redux actions as they occur, you can observe that the DIRECT_LINE/QUEUE_INCOMING_ACTIVITY action happens immediately so you know that Direct Line is receiving the activities about 5 seconds before they're actually rendered.

As I mentioned in a previous comment, this may or may not be related to a rendering delay that only reproes in Emulator (and is not caused by proactive messages): microsoft/BotFramework-Emulator#2262

[MikeCardiff]

Just wanted to chime in and say I'm also experiencing this issue using webchat/directline. We're using proactive messages for handoff and inactivity prompts.

Here's the websocket messages from a conversation resumed from the directline cache in case it's of any help. The bottom two are the delayed proactive messages. They are recieved at the same time as other messages but have a delay before being shown in UI.

Could the issue be related to the activity replyToId? The value set on proactive messages does not match any in the conversation. Prehaps webchat is waiting to find the matching ID before showing the message?

[compulim]

I will investigate this, added to R14 To-do board. It's about the 3rd thing on my list now.

[mmadziamcx]

I think @MikeCardiff is correct. We are experiencing a similar issue using Proactive messages. Depending on the perspective, its either an issue with the Bot framework setting this property when it shouldn't, or the Web Chat client making a bad assumption on how to handle messages with the replyToId property.

According to the web chat client framework documentation https://github.com/microsoft/BotFramework-WebChat/blob/master/docs/ACCESSIBILITY.md#implementations

"When a message with a replyToId property arrives, Web Chat will check if it received the activity with the specified ID:
If no activities were received with the specified ID, Web Chat will wait up to 5 seconds for the referencing activity to arrive."

The replyToId values being set for ContinueConversationAsync messages are not in the proper conversationId format, the value is being set as a GUID. Since the value exists, the client is waiting on a message with an Id property that will match the replyToId. This will never occur as the replyToId value is not even in the same format as the message Ids.

As proactive messages are not a reply to a previous message, it would follow that no replyToId property should be set for those activities. The web chat client documentation above also states "When a message without a replyToId property arrives, or is the first activity in the transcript, Web Chat will render the activity immediately." So it appears the client is anticipating some messages not containing this property, and will render those messages immediately.

[rbohac]

In the botbuilder-dotnet source within ActivityEx.cs:535 it sets the replyToId to the value contained in Activity.Id of the turnContext. I'm not sure if there is a valid reason to ever do this on a proactive message.

However I was able to find a workaround. When sending the proactive message you can null Activity.Id and the framework will end up passing null in the replyToId field, which then eliminates the queueing delay in the webchat client

public async Task<IActionResult> Get()
       {
           foreach (var conversationReference in _conversationReferences.Values)
           {
               await ((BotAdapter)_adapter).ContinueConversationAsync(_appId, conversationReference,
                               async (ITurnContext turnContext2, CancellationToken cancellationToken2) =>
                               {
                                   var activity = MessageFactory.Text("proactive hello 2");                                   
                                   turnContext2.Activity.Id = "";
                                   await turnContext2.SendActivityAsync(activity);
                               }
                               , default(CancellationToken));
           }
           return new ContentResult()
           {
               Content = "<html><body><h1>Proactive messages have been sent.</h1></body></html>",
               ContentType = "text/html",
               StatusCode = (int)HttpStatusCode.OK,
           };
       }

[MikeCardiff]

The workaround by @rbohac worked for me too.

I'd tried setting the replyToId to null but it would get assigned a new ID. Didn't think of setting the ID of the activity it was replying to. Good call!

[primle]

For developing a bot with composer, one can adapt the workaround by @rbohac to be included in a custom action, which should be called after the OAuth Login Card.

Simply set the activity id of the dialogcontext property to an empty string. e.g.

public override Task<DialogTurnResult> BeginDialogAsync(DialogContext dc, object options = null, CancellationToken cancellationToken = default(CancellationToken))
{
        dc.Context.Activity.Id = "";
        ...
}