Input message displayed (shortly) above bot message

[jvanderbiest]

Using the latest master webchat.js, I have this strange behaviour when I talk to the bot that user message is first displayed above the last bot message, then after a new bot reply it is positioned correctly => inbetween the last bot reply and the previous bot reply. I can reproduce this also on the examples.

See video
https://youtu.be/0tkQ22iFZpQ

[corinagum]

Hi @jvanderbiest, one of our users recently discovered that this was due to a computer's time being behind official time. Please see this issue: #1890

[jvanderbiest]

hi @corinagum,
My time settings are correct and I still have this issue. My Date & Time settings are set to automatically on Windows 10. I still think it's an issue as I was able to reproduce it on multiple boxes.

[compulim]

@jvanderbiest can you check timezone in your browser machine?

I checked the code here, this is where we find the correct place to insert the activity into.

• nextActivity is the activity that we will be adding into the transcript. In your video, this is the message which the user is sending (while it is sending, not being sent)
• nextActivity.timestamp is generated from local timestamp, which is the code here and here
• Line 38: We grab the timestamp out from nextTimestamp, we will use this timestamp to find the correct place to insert the activity into
• Line 54: We find the position from top to bottom, where the activity.timestamp is larger than the one in nextTimestamp (the one we are holding onto), so we should insert before that

It is being corrected momentarily because after the message is successfully sent, our server will put the server's clock in timestamp field, overriding the value generated by postActivitySaga.js:54. To me, it seems like there is a clock skew between your client's box and the server. We use UTC for comparison so I believe it should be good.

Could you help us to debug into a few things?

• Line 38: Put a console.log(nextTimestamp + ' ' + new Date()); there
  • Could you verify nextTimestamp is a value very close to new Date()? And can you verify the timestamp is correct? Note that it is in UTC+00 timezone, not your local timezone.
• Line 56: Add console.log(nextActivities); and console.log(indexToInsert);
  • Could you verify if the indexToInsert is correctly pointing to the place the activity should be inserted chronologically?
  • Could you verify activities all have correct timestamp?

Instead of simply appending to the activities array, we need to find the correct place to insert the activity because activities can be come from server out-of-order. One way we could perma-fix that is to sync clock skew from time to time.

[corinagum]

Closing due to inactivity.

[MStumpp]

I am experiencing the same problem as @Slayouth when using WebChat (https://cdn.botframework.com/botframework-webchat/latest/webchat.js) and botbuilder 4.4.0. Works as expected in Bot Emulator.

I deployed to Azure Web App which has UTC timezone. I configured my local dev machine to run UTC as well.

Unfortunately, this is a show stopper.

[corinagum]

@MStumpp could you debug with @compulim's instructions above and get back to us?

[MStumpp]

Results of debug test:
1.) Bot shows welcome message:
Line 38: 1559614371923 Tue Jun 04 2019 04:12:08 GMT+0200 (Mitteleuropäische Sommerzeit)

• "very close" is subjective. anyway, representing 1559613852303 as date: Jun 04 2019 2019 04:12:51.923 GMT+02:00
• timestamp is correct
  Line 56:
  nextActivities: timestamp is "2019-06-04T02:12:51.9231008Z"
  indexToInsert: -1

=> nextTimestamp + ' ' + new Date() => 1559614371923 Tue Jun 04 2019 04:12:08 GMT+0200 shows a little gap of approx. 45s. If user adds new message in less than 45s after bot shows welcome message, user's message is placed on top (which is wrong). however, when user adds new message after 45s after bot shows welcome message, all is fine.

[MStumpp]

Any updates on this?

[corinagum]

Assigning to @compulim for investigation

[compulim]

Yes, very close is subjective. 😂

Looks like the local machine has a clock skew of about 43 seconds, when compare to our servers.

So, in order to fix this without asking the user to update their clock, we need to add a "de-clock-skew" logic to reducers/activities.js.

Currently we don't have any REST API to measure the clock skew on the client box, one will need to use a public API to estimate the clock skew and compensate for it while inserting the activity.

p.s. we can't use fetch to estimate the clock skew because "Date" is a forbidden header name and cannot be retrieved programmatically.

[compulim]

After talking to the channel team, the other way, is to use the first activity as a base for the clock for both outgoing and incoming activity.

The sorting problem we witness here is because the outgoing activity cannot be timestamped using an accurate clock. The client clock has skewed too much (> 2s) compare to the server, thus, the outgoing activity we timestamped is in wrong position.

We should try this approach and see how it works:

1. When the first incoming activity come, we use it as base clock, i.e. t = 0
2. When subsequent incoming activities come, we rebase the time field using t and set it to relativeTime property (not to confuse with the original time field)
3. For outgoing activities, we will stamp it using a relative clock based on t. If t is not available, we will set it to 0

[MStumpp]

Why not use some incrementing counter instead to ensure correct order?

[akashgosai]

On using the previous version's (v3) latest/botchat,js and latest/botchat.css, this issue seems to be absent consistently. Is there any way we can make use of previous botchat.js while availing the current features of webchat.js (v4) (e.g. card components) ? The link for both are pasted here, have a look.
https://cdn.botframework.com/botframework-webchat/latest/botchat.js
https://cdn.botframework.com/botframework-webchat/latest/botchat.css

[compulim]

Can't use counter because we plan to support update activity and resume conversation (loading chat history). These activities will come out-of-order and need to be sorted by time.

The steps outlined in my comment above should fix most of the issues. Just need time to implement them.

[MStumpp]

Do we have a time line for a fix? Thx

[corinagum]

No current timeline - this issue is currently filed in our Backlog.

[compulim]

Would love to see if this fit in 4.6, looks like it hit quite some users.