[BUG] Call is not ended after page refresh

[ostap0207]

• I have verified that the issue occurs with the latest twilio.js release and is not marked as a known issue in the CHANGELOG.md.
• I reviewed the Common Issues and open GitHub issues and verified that this report represents a potentially new issue.
• I verified that the Quickstart application works in my environment.
• I am not sharing any Personally Identifiable Information (PII)
  or sensitive account information (API keys, credentials, etc.) when reporting this issue.

Code to reproduce the issue:

1. Start a call in Twilio provided quickstart app in FF 105.0.2
2. Go to Twilio console (https://console.twilio.com/us1/monitor/logs/calls) and observe that the call is "In Progress"
3. Refresh quickstart app page in FF
4. Refresh Twilio console

Expected behavior:

The call is marked as ended in Twilio console

Actual behavior:

The call is not marked as ended in Twilio console

The call only is marked as ended after 15 - 20 seconds

Software versions:

• Browser(s): FF 105.0.2
• Operating System: MacOs 12.4
• twilio.js: 2.1.1

[charliesantos]

Hi @ostap0207 , do you see the same 15-20s delay when you perform the same steps on other browsers (Chrome, Safari)?

[ostap0207]

Only see it in Firefox

[charliesantos]

@ostap0207 thanks.
Can you please do a quick test for me. In your app, add the following and see if the handler is executed?
You will need to enable persistent log though, so that you can still see the console log.
https://firefox-source-docs.mozilla.org/devtools-user/settings/index.html#common-preferences

window.addEventListener('unload', () => console.log('on unload'));

What this does is, we will know if our cleanup routine is being executed on the client, or if it's a server issue.

[ostap0207]

Here are the full Twilio logs (this is from default Twilio quickstart app):

11:53:37.332 Setting up VSP twilio.min.js:1:105480
11:53:37.332 Initializing preferred transport backoff using config:  
Object { factor: 2, maxDelay: 1000, randomisationFactor: 0.4 }
twilio.min.js:1:105480
11:53:37.335 Initializing primary transport backoff using config:  
Object { factor: 2, initialDelay: 100, maxDelay: 20000, randomisationFactor: 0.4 }
twilio.min.js:1:105480
11:53:37.335 WSTransport.open() called... twilio.min.js:1:105480
11:53:37.335 Attempting to connect... twilio.min.js:1:105480
11:53:37.335 Closing and cleaning up WebSocket... twilio.min.js:1:105480
11:53:37.335 No WebSocket to clean up. twilio.min.js:1:105480
11:53:37.565 WebSocket opened successfully. twilio.min.js:1:105480
11:53:37.565 Setting token and publishing listen twilio.min.js:1:105480
11:53:37.905 Stream is ready twilio.min.js:1:105480
11:53:41.625 signalingState is "have-local-offer" twilio.min.js:1:105480
11:53:41.626 dtlsTransportState is "new" twilio.min.js:1:105480
11:53:41.627 pc.iceGatheringState is "gathering" twilio.min.js:1:105480
11:53:41.628 ICE Candidate: {"candidate":"candidate:0 1 UDP 2122252543 10.200.0.205 64467 typ host","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7187e0e3"} twilio.min.js:1:105480
11:53:41.628 ICE Candidate: {"candidate":"candidate:1 1 TCP 2105524479 10.200.0.205 9 typ host tcptype active","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7187e0e3"} twilio.min.js:1:105480
11:53:41.629 ICE Candidate: {"candidate":"candidate:0 2 UDP 2122252542 10.200.0.205 65507 typ host","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7187e0e3"} twilio.min.js:1:105480
11:53:41.630 ICE Candidate: {"candidate":"candidate:1 2 TCP 2105524478 10.200.0.205 9 typ host tcptype active","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7187e0e3"} twilio.min.js:1:105480
11:53:41.630 ICE Candidate: {"candidate":"","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7187e0e3"} twilio.min.js:1:105480
11:53:41.630 pc.iceGatheringState is "complete" twilio.min.js:1:105480
11:53:41.631 ICE Candidate: null twilio.min.js:1:105480
11:53:41.971 signalingState is "stable" twilio.min.js:1:105480
11:53:41.976 pc.iceConnectionState is "checking" twilio.min.js:1:105480
11:53:42.002 dtlsTransportState is "connecting" twilio.min.js:1:105480
11:53:42.003 pc.iceConnectionState is "connected" twilio.min.js:1:105480
11:53:42.004 Media connection established. twilio.min.js:1:105480
11:53:42.067 dtlsTransportState is "connected" twilio.min.js:1:105480
11:53:54.329 Navigated to https://***.ngrok.io/
11:53:54.385 Received websocket close event code: 1001. Reason: twilio.min.js:1:105480
11:53:54.385 Closing and cleaning up WebSocket... twilio.min.js:1:105480
11:53:54.385 Preferred URI set; backing off. twilio.min.js:1:105480
11:53:54.386 Will attempt to reconnect Websocket to preferred URI in 123ms twilio.min.js:1:105480
11:53:54.386 Preferred backoff start; 1665392034386 twilio.min.js:1:105480
11:53:54.386
Received transportClose from pstream twilio.min.js:1:105270
11:53:54.386 Stream is offline twilio.min.js:1:105480
11:53:54.511 Max preferred backoff attempt time exceeded; falling back to primary backoff. twilio.min.js:1:105480
11:53:54.511 Will attempt to reconnect WebSocket in 123ms twilio.min.js:1:105480
11:53:54.511 Primary backoff start; 1665392034512 twilio.min.js:1:105480
11:53:54.601 Disconnecting... twilio.min.js:1:105480
11:53:54.602 dtlsTransportState is "closed" twilio.min.js:1:105480
11:53:54.604 PStream.destroy() called... twilio.min.js:1:105480
11:53:54.604 WSTransport.close() called... twilio.min.js:1:105480
11:53:54.604 Closing and cleaning up WebSocket... twilio.min.js:1:105480
11:53:54.604 No WebSocket to clean up. twilio.min.js:1:105480
11:53:54.604 Stream is offline twilio.min.js:1:105480
11:53:54.604 on unload quickstart.js:30:51

I can see on unload gets triggered as Twilio tries to end the call and on unload is logged.

We did some more testing with different Twilio versions and found
2.1.1 - issue reproducible
2.1.0 - issue reproducible
2.0.1 - issue not reproducible

So it looks like some changes between 2.0.1 and 2.1.0 have started causing this issue.

[ostap0207]

After some more testing we found that issue doesn't exist in 2.1.0-rc1, but exists in 2.1.0-rc2 2.1.0-rc1...2.1.0-rc2

[charliesantos]

Thanks @ostap0207 for the additional information. This definitely helps. As you mentioned, the call shows as ended after around 15-20s. How long does it take on Chrome?

[ostap0207]

On Chrome (and on 2.0.1 in FF) the call is immediately marked as completed as soon as the page is reloaded, as expected.

[ostap0207]

Are there any estimates of when this issue can be fixed?

[charliesantos]

Hi @ostap0207 . What is your use case that requires you to see the call ended in less than 15s on console?

[ostap0207]

I can see several issues:

1. This prevents us to receive a webhook that the call has ended in time - which means we have invalid data about the call end time and could make some logic invalid down the line
2. I would assume this causes the call to cost more than it should if it's marked as ended after 15-20 s
3. It seems big change from existing behavior on which many can rely

We also have a specific use case where after refresh we need to immediately establish another call for the same user, but because the call is not marked as ended for the user and internal constraints that the user can only have one call at a time then this functionality fails.

[charliesantos]

@ostap0207 thanks for providing more context. It'll help us prioritize the issue. As a workaround for now, can you try listening to beforeunload event and call device.destroy()? Please let me know if this works.

[ostap0207]

Thanks!
We were considering using this workaround, but it does not work well for us and can cause unexpected behaviours. The reason is that our service runs on clients' websites, client might define their own beforeunload handler after ours that can prevent page refresh as beforeunload event is cancelable.

[charliesantos]

Thanks @ostap0207 . I'll create an internal ticket to investigate this further.

[ostap0207]

Hello, any updates on this and when can this be fixed?

[charliesantos]

Hi @ostap0207 thanks for the ping! This is under the radar but no updates on ETA yet.

[oskarkook]

Hi @charliesantos! Are there any updates on this?

[charliesantos]

Hi @oskarkook . Thanks for the ping. Apologies for the delay but we don't have any updates yet on this.

[charliesantos]

Happens on other browsers as well #210

[msalei]

Hi @charliesantos! Any updates on this? Thanks!

[charliesantos]

Hey everyone, are you all passing any value to maxCallSignalingTimeoutMs

[ostap0207]

Hey, we are not using specifying maxCallSignalingTimeoutMs

[charliesantos]

We've found out that this issue started happening since the introduction of signaling reconnection feature. The backend is waiting on the client to reconnect by default. The problem is that the backend is currently not respecting the value provided via maxCallSignalingTimeoutMs parameter. We will update this behavior and keep you posted.

[electrovir]

Hey everyone, are you all passing any value to maxCallSignalingTimeoutMs

We are also not using maxCallSignalingTimeoutMs.

[charliesantos]

Fixed in 2.10.2 which will get released soon.