Cannot hear any ringing tone when there is an incoming call

[benparsons]

Steps to reproduce

Customer reports they are unable to hear the ringing tone when they have an incoming call. However, when the call is answered audio works.

Could be related to: #20831

Outcome

What did you expect?

to hear the ringing tone

What happened instead?

nothing heard, but when the call is picked up audio is correctly heard.

2022-06-06.13-39-18.mp4

-- @belakalotay, #20832 (comment)

See rageshake.

Operating system

Windows

Browser information

Chrome version 98.0.4758.102

URL for webapp

N/A

Application version

N/A

Homeserver

No response

Will you send logs?

Yes

no-sound-web.zip

[SimonBrandner]

@dbkr, this is a common issue? I have yet to see it happen

@benparsons, what does the customer have set here?

[benparsons]

Hi @chagai95 one for when you're back at a desk. We're having trouble repro'ing, can you help with more information?

[chagai95]

Hey, I am getting this a lot, and I'll try adding more info as soon as I get this again. I have seen others have the same issue, so the exact browser information is not that important I believe, nevertheless: Chrome 98.0.4758.102 on Windows.

[chagai95]

This might be sometimes because Chrome does not allow to play sound before a first user interaction. But that might only be some of the cases this happens and not all of them.

We might be able to solve this I guess in Desktop because we can change that?

But I guess we are looking to reproduce cases where there was user interaction after a refresh and the issue still persists.

[MadLittleMods]

@chagai95 Did you ever submit debug logs when this occurred? I'm not seeing a rageshake log for this issue or around this time for your @chagai95:matrix.org Matrix user.

Are you still seeing this problem?

[chagai95]

Hey yes here are the logs and a recording I made showing this I just encountered this today:

no-sound-web.zip

https://aarenet-my.sharepoint.com/:v:/p/chagai_friedlander/Ecyt4D7AxIVOo0yHlylKny8BWSxwLuq9WP6itQPlwOzn3A

chrome_c4VHgwDprd.mp4

[turt2live]

I'm strongly inclined to believe that this is related to the interaction requirements of Chrome. If someone is able to confirm that they do not see the issue after clicking on the page a bunch then will write it off as that.

[chagai95]

I'll try that next time I encounter the issue. I'll try reading more about those chrome interaction requirements, but I was wondering if you have any good suggestions where I could read about that? Also if it's a chrome thing, would it be possible to change these requirements for electron? Maybe it even already works fine on electron...)

I think (at least for us at Aarenet) it's a pretty high priority to be able to reliably play ringtone so people know when they are getting an incoming call. Therefore we'll probably want to go the distance and at least configure electron to be able to do that.

Just to clarify, do you think this issue is different than the issue where there user can't hear the ringback? Because in that case there is always a user interaction (phoning someone) before the issue happens.

[chagai95]

Some more logs, just saw this happening after a lot of user interaction, you should be able to see the user interaction in the logs as well no? This is on Electron so I believe there was also no refreshing involved but I might be wrong about that

logs-0003.log.gz
logs-0004.log.gz
logs-0005.log.gz
logs-0006.log.gz
logs-0007.log.gz
logs-0008.log.gz
logs-0009.log.gz
logs-0000.log.gz
logs-0001.log.gz
logs-0002.log.gz

[belakalotay]

I'm strongly inclined to believe that this is related to the interaction requirements of Chrome. If someone is able to confirm that they do not see the issue after clicking on the page a bunch then will write it off as that.

The following video demonstrates both problems:

• the missing ringing tone (which is reported in this ticket)
• and also the missing ringback tone (reported under: Can not hear ringback when calling someone (outgoing call) #20831)
  Both problems seem to go hand-in-hand and happen on a regular basis.

2022-06-06.13-39-18.mp4

As you can see in the video, "clicking on the page a bunch" didn't help, the problem persists.
Please find the related logs attached.

rageshake_2.zip

[MadLittleMods]

@belakalotay That reproduction video is fantastic! Thanks for the voiceover explaining the problem and clear demonstration of the both issues!

I've added some more logging around how we play sound effects to try to narrow this down more, matrix-org/matrix-react-sdk#8772. Once that PR merges and is updated in your anConnect fork, send another set of debug logs 🤞

[belakalotay]

We have reproduced the problem with the additional logs.
The attached log-0.log file contains logs for two calls, the ringback tone was NOT audible for both of them:

• the first one (at ~9:16) was terminated without an answer,

• the second one (at ~9:18) has been answered by the called party and the voice conversation had no audio problems.

log-0.log
issue.txt

[MadLittleMods]

@belakalotay Looking at your logs (cat "log-0.log" | grep -Ei "CallHandler|Call state|Call completed|Call ID"), I see:

From the call at 9:16, it looks like you called for 3 seconds before hanging up and according to the logs, the ringbackAudio was playing.

2022-09-02T09:16:32.942Z I Call state in !jftLOgptzCZyadVdMf:anconnect-server.aarenet.com changed to wait_local_media
2022-09-02T09:16:34.378Z I Call state in !jftLOgptzCZyadVdMf:anconnect-server.aarenet.com changed to create_offer
2022-09-02T09:16:34.632Z I Call state in !jftLOgptzCZyadVdMf:anconnect-server.aarenet.com changed to invite_sent
2022-09-02T09:16:34.647Z I CallHandler.play(ringbackAudio): beginning of function
2022-09-02T09:16:34.649Z I CallHandler.play(ringbackAudio): attempting to play audio
2022-09-02T09:16:34.664Z I CallHandler.play(ringbackAudio): playing audio successfully
2022-09-02T09:16:37.209Z I CallHandler.pause(ringAudio): beginning of function
2022-09-02T09:16:37.210Z I CallHandler.pause(ringAudio): pausing audio
2022-09-02T09:16:37.213Z I Call state in !jftLOgptzCZyadVdMf:anconnect-server.aarenet.com changed to ended
2022-09-02T09:16:37.234Z I CallHandler.pause(ringbackAudio): beginning of function
2022-09-02T09:16:37.235Z I CallHandler.play(callendAudio): beginning of function
2022-09-02T09:16:37.242Z I CallHandler.pause(ringbackAudio): pausing audio
2022-09-02T09:16:37.243Z I CallHandler.play(callendAudio): attempting to play audio
2022-09-02T09:16:37.243Z I Call completed. Call ID: 1662110192941xV9ent2ck9STAGt7, virtual room ID: !sSMlDAJSWeMpyRixAS:anconnect-server.aarenet.com, user-facing room ID: !jftLOgptzCZyadVdMf:anconnect-server.aarenet.com, direction: outbound, our Party ID: DYZQXUWWOR, hangup party: local, hangup reason: user_hangup
2022-09-02T09:16:37.264Z I CallHandler.play(callendAudio): playing audio successfully

From the call at 9:18, the ringbackAudio played for 12 seconds until the call connected. The call lasted for 5 minutes and was hungup.

2022-09-02T09:17:59.554Z I Call state in !mZaLNoWJVFKzkNdQpp:anconnect-server.aarenet.com changed to wait_local_media
2022-09-02T09:18:00.931Z I Call state in !mZaLNoWJVFKzkNdQpp:anconnect-server.aarenet.com changed to create_offer
2022-09-02T09:18:01.190Z I Call state in !mZaLNoWJVFKzkNdQpp:anconnect-server.aarenet.com changed to invite_sent
2022-09-02T09:18:01.209Z I CallHandler.play(ringbackAudio): beginning of function
2022-09-02T09:18:01.210Z I CallHandler.play(ringbackAudio): attempting to play audio
2022-09-02T09:18:01.226Z I CallHandler.play(ringbackAudio): playing audio successfully
2022-09-02T09:18:13.918Z I Got answer for call ID 1662110279554AF9FYWIJJpShGRlR from party ID kLHHN1fj
2022-09-02T09:18:13.918Z I Choosing party ID kLHHN1fj for call ID 1662110279554AF9FYWIJJpShGRlR
2022-09-02T09:18:13.919Z I Call state in !mZaLNoWJVFKzkNdQpp:anconnect-server.aarenet.com changed to connecting
2022-09-02T09:18:13.939Z I CallHandler.pause(ringbackAudio): beginning of function
2022-09-02T09:18:13.940Z I CallHandler.pause(ringbackAudio): pausing audio
2022-09-02T09:18:13.952Z I Call ID 1662110279554AF9FYWIJJpShGRlR: ICE connection state changed to: checking
2022-09-02T09:18:13.994Z I Call ID 1662110279554AF9FYWIJJpShGRlR: ICE connection state changed to: connected
2022-09-02T09:18:13.994Z I Call state in !mZaLNoWJVFKzkNdQpp:anconnect-server.aarenet.com changed to connected
2022-09-02T09:23:17.496Z I CallHandler.pause(ringAudio): beginning of function
2022-09-02T09:23:17.497Z I CallHandler.pause(ringAudio): pausing audio
2022-09-02T09:23:17.504Z I Call state in !mZaLNoWJVFKzkNdQpp:anconnect-server.aarenet.com changed to ended
2022-09-02T09:23:17.526Z I CallHandler.play(callendAudio): beginning of function
2022-09-02T09:23:17.530Z I CallHandler.play(callendAudio): attempting to play audio
2022-09-02T09:23:17.530Z I Call completed. Call ID: 1662110279554AF9FYWIJJpShGRlR, virtual room ID: !ZjahvwwFIonxcmazeY:anconnect-server.aarenet.com, user-facing room ID: !mZaLNoWJVFKzkNdQpp:anconnect-server.aarenet.com, direction: outbound, our Party ID: DYZQXUWWOR, hangup party: local, hangup reason: user_hangup
2022-09-02T09:23:17.554Z I CallHandler.play(callendAudio): playing audio successfully

---

Things seem to behaving as expected from the app perspective. We can't really track beyond this point to see if your browser or system is actually emitting sound though.

Since you were the one making the calls (outgoing calls), this is more applicable to #20831 since the ringbackAudio was in play here.

---

From a general Element perspective, since we only have one CallHandler instance, I could potentially see how multiple incoming calls could mess with play/pausing ringAudio weirdly. Also a potential for ringbackAudio if you're somehow able to make multiple outgoing calls in Element. But to be clear, this is not the case from your logs.

Your earlier video demonstrating both issues still makes this a real problem though. I just don't know what and where we can debug to get the proper information on why audio isn't making it out from when the browser says the audio is playing successfully to your speakers.

If it was a browser interaction requirement, we should be seeing a NotAllowedError when playing the audio but that's not the case in these logs.

[benparsons]

Customer reports this is "being noticed more and more in the field."

[MadLittleMods]

@chagai95 @belakalotay We've just merged some additional debug logs around the <audio> element being muted, volume, and various error states, matrix-org/matrix-react-sdk#9642

Just like last time, once that PR makes it to a release and is updated in your anConnect fork, send another set of debug logs, video, timestamp, etc 🤞

You can also enable some additional logging of <audio> events by running these snippets in the developer tools console:

Turn on extra logging:

mxSettingsStore.setValue('debug_legacy_call_handler', null, 'device', true);

Turn off extra logging:

mxSettingsStore.setValue('debug_legacy_call_handler', null, 'device', false);

[MadLittleMods]

Interesting issue #19294 that may be related