1902263 - Video stops (but not audio) when connecting a Bluetooth Speaker on Android (Samsung)

Status: RESOLVED FIXED

(Core :: Audio/Video, defect, P2)

Description

[Julien Wajsberg [:julienw]]

STR:

1. Read a video on youtube on the phone speaker (no bluetooth speaker is connected)
2. Connect a bluetooth speaker

=> The video stops, but not the audio. A spinner appears.

Seeking the video resumes the video playing.

Profile with media preset and logs => https://share.firefox.dev/4enESxU

This is on Android 12, Samsung S10e, Firefox nightly.

Comment 1

[Andreas Pehrson [:pehrsons]]

I'm seeing something similar. There are no cubeb logs in the parent process in your profile though, so not sure if it's the same issue.

Comment 2

[Andreas Pehrson [:pehrsons]]

When switching output device mid-playback I see aaudio_stream_get_position getting stuck for some time. I guess the timing info restarts from 0 without us knowing. Sounds like it might be a bug in AAudioStream_getFramesWritten (compared to docs).

Comment 3

[John Lin [:jhlin][:jolin]]

I did some local tests. It looks like this issue is caused by obsolete timing info used after stream reinitialization.

Here is the log:

Before device changed, the last stm->timing_info was { output_frame_index:364800, tstamp:385486791446659, output_latency:10005 }

06-27 17:55:01.959  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1686:AAudioTimingInfo idx:364800 tstamp:385486791446659 latency:10005
06-27 17:55:01.959  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1698:aaudio_stream_get_position: 363229 frames

After device change, the device was reinitialized:

06-27 17:55:01.972  4065  4738 I Gecko   : [Parent 4065: Unnamed thread 6dcbbf0120]: E/cubeb cubeb_aaudio.cpp:1020:Audio device change, reinitializing stream
06-27 17:55:01.973  4065  4904 I Gecko   : [Parent 4065: Unnamed thread 6dcbbf0120]: E/cubeb cubeb_aaudio.cpp:1552:STOPPING stream 0x6dc5e25080: 3 (0 13)

and aaudio_stream_destroy_locked() was called and stm->timing_info buffers should be invalidated:

06-27 17:55:01.975  4065  4904 I Gecko   : [Parent 4065: Unnamed thread 6dcbbf0120]: E/cubeb cubeb_aaudio.cpp:1137:aaudio_stream_destroy_locked
...
06-27 17:55:01.997  4065  4904 I Gecko   : [Parent 4065: Unnamed thread 6dcbbf0120]: E/cubeb cubeb_aaudio.cpp:1340:Cubeb stream (0x6dc5e25080) INIT success
06-27 17:55:01.997  4065  4904 I Gecko   : [Parent 4065: Unnamed thread 6dcbbf0120]: E/cubeb cubeb_aaudio.cpp:1444:STARTING stream 0x6dc5e25080: 1 (0 2)
06-27 17:55:02.006  4065  4905 I Gecko   : [Parent 4065: Unnamed thread 6dcbbf0890]: E/cubeb cubeb_aaudio.cpp:718:AAudioStream_getTimestamp failure for output: AAUDIO_ERROR_INVALID_STATE

But, the old stm->timing_info was still in effect for a while until the next callback:

06-27 17:55:02.006  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1686:AAudioTimingInfo idx:364800 tstamp:385486791446659 latency:10005
06-27 17:55:02.006  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1698:aaudio_stream_get_position: 365506 frames
06-27 17:55:02.006  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1686:AAudioTimingInfo idx:364800 tstamp:385486791446659 latency:10005
06-27 17:55:02.007  4065  4905 I Gecko   : [Parent 4065: Unnamed thread 6dcbbf0890]: E/cubeb cubeb_aaudio.cpp:718:AAudioStream_getTimestamp failure for output: AAUDIO_ERROR_INVALID_STATE
06-27 17:55:02.007  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1698:aaudio_stream_get_position: 365526 frames
06-27 17:55:02.007  4065  4905 I Gecko   : [Parent 4065: Unnamed thread 6dcbbf0890]: E/cubeb cubeb_aaudio.cpp:718:AAudioStream_getTimestamp failure for output: AAUDIO_ERROR_INVALID_STATE
06-27 17:55:02.015  4065  4103 I Gecko   : [Parent 4065: cubeb_log]: E/cubeb aaudio output data cb on stream 0x6dc5e25080: state 1 (3), num_frames: 4800
06-27 17:55:02.015  4065  4103 I Gecko   : [Parent 4065: cubeb_log]: E/cubeb aaudio output data cb on stream 0x6dc5e25080: state 4 (3), num_frames: 4800
06-27 17:55:02.015  4065  4103 I Gecko   : [Parent 4065: cubeb_log]: E/cubeb aaudio output data cb on stream 0x6dc5e25080: state 4 (3), num_frames: 4800
06-27 17:55:02.025  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1686:AAudioTimingInfo idx:364800 tstamp:385486791446659 latency:10005
06-27 17:55:02.025  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1698:aaudio_stream_get_position: 366407 frames
06-27 17:55:02.047  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1686:AAudioTimingInfo idx:364800 tstamp:385486791446659 latency:10005
06-27 17:55:02.047  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1698:aaudio_stream_get_position: 367486 frames
...
06-27 17:55:02.090  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1686:AAudioTimingInfo idx:364800 tstamp:385486791446659 latency:10005
06-27 17:55:02.090  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1698:aaudio_stream_get_position: 369538 frames
...
06-27 17:55:02.093  4065  4905 I Gecko   : [Parent 4065: Unnamed thread 6dcbbf0890]: E/cubeb cubeb_aaudio.cpp:738:Latency in frames (output): 14294 (423229211ms)

but stm->previous_clock held the value 369538, so smaller value than it will be rejected:

06-27 17:55:02.093  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1686:AAudioTimingInfo idx:14400 tstamp:385487101093149 latency:14294
06-27 17:55:02.093  4065  4258 I Gecko   : [Parent 4065: AudioIPC Server RPC]: E/cubeb cubeb_aaudio.cpp:1698:aaudio_stream_get_position: 369538 frames

I don't see how this would happen. The old value lasted tens of milliseconds, so it's unlikely a scheduling/racing issue.

Comment 4

[John Lin [:jhlin][:jolin]]

It turns out that stm->previous_clock is not being reset when re-initialization, reinitialize_stream() calls aaudio_stream_init_impl(), which doesn't clear the value (only assigned in user-called aaudio_stream_init()).

It makes the test fail and incorrectly use stm->timing_info even when it's not updated.

Should we keep the last stm->previous_clock value and add it to new positions?

Comment 5

[Paul Adenot (:padenot)]

(In reply to John Lin [:jhlin][:jolin] from comment #4)

It turns out that stm->previous_clock is not being reset when re-initialization, reinitialize_stream() calls aaudio_stream_init_impl(), which doesn't clear the value (only assigned in user-called aaudio_stream_init()).

It makes the test fail and incorrectly use stm->timing_info even when it's not updated.

Should we keep the last stm->previous_clock value and add it to new positions?

Yes to all of that. Generally when we reinit we need to reset anything, seem like a few things have been missed.

Comment 6

[John Lin [:jhlin][:jolin]]

Attachment: Bug 1902263 - Update libcubeb to revision 063a090.

Comment 7

[Phabricator Automation]

Comment on attachment 9411569 [details]
Bug 1902263 - Update libcubeb to revision 063a090.

Revision D215931 was moved to bug 1877948. Setting attachment 9411569 [details] to obsolete.

Comment 8

[John Lin [:jhlin][:jolin]]

Comment on attachment 9411569 [details]
Bug 1902263 - Update libcubeb to revision 063a090.

Wrong bug number in the previously attached patch. The correct cubeb PR is: https://github.com/mozilla/cubeb/pull/792

Comment 9

[John Lin [:jhlin][:jolin]]

Attachment: Bug 1902263 - update libcubeb to revision bbbe5bb.

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4aa0834a7a22
update libcubeb to revision bbbe5bb. r=cubeb-reviewers,padenot

Comment 11

[Cristina Horotan [:chorotan]]

https://hg.mozilla.org/mozilla-central/rev/4aa0834a7a22