Vash63 Reporter
	Description • 6 years ago

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0
Build ID: 20180309100425

Steps to reproduce:

1. Play a video on Youtube (Other audio sources work also).
2. Open up https://www.google.com/search?q=dutch+to+english&ie=utf-8&oe=utf-8&client=firefox-b-1-ab

Note, this cannot be duplicated on translate.google.com - only on the search results page with the google translate card widget at the top.


Actual results:

Audio in Youtube continues playing but with horrible crackling noises and a delayed echo of everything. If I pause or stop the YT playback, the corrupted echo continues at about a 1-2s delay. This issue continues until I fully close Firefox and start the browser again.


Expected results:

Audio should continue to play without corruption.

	Vash63 Reporter
	Comment 1 • 6 years ago

I cannot duplicate this in either Chromium on the same system, or if I boot to Windows and try it in Firefox on Windows. I can duplicate this on 58 Stable in Linux.

	David Olah
	Comment 2 • 6 years ago

Managed to reproduce the bug on Ubuntu 16.04, Nightly 61.0a1 (2018-03-13) only at first try.

	Maire Reavy [:mreavy]
	Comment 3 • 6 years ago

p1 at least for investigation of what the URL in point 2 of comment 0 is doing, audio-wise (I presume GetUserMedia or equivalent).  Given this is apparently linux-only (worth testing on Mac), this may be a Pulse issue.

	Vash63 Reporter
	Comment 4 • 6 years ago

I also have a Mac running High Sierra on Nightly 2018-05-09 and cannot reproduce it there.

	Nico Grunbaum [:ng, @chew:mozilla.org]
	Comment 5 • 6 years ago

On Ubuntu 17.10, I can not reproduce this on today's nightly 2018-05-10, but I can reproduce it in yesterday's nightly.

	Nico Grunbaum [:ng, @chew:mozilla.org]
	Comment 6 • 6 years ago

I take that back, I can reproduce it on nightly if I use a different video. The problem doesn't seem to present it self with low audio levels. Here is a video that demonstrates that behavior:  https://www.youtube.com/watch?v=SBljWDJFe7c with both quiet and loud audio.

	Alex Chronopoulos [:achronop]
	Comment 7 • 6 years ago

Hi and sorry for the late response, do you still have the issue? If yes can you try to reproduce it with a custom binary that I will give you?

	Nico Grunbaum [:ng, @chew:mozilla.org]
	Comment 8 • 6 years ago

I tried today's nightly in Ubuntu 18.04 and can no longer reproduce this.

	Alex Chronopoulos [:achronop]
	Comment 9 • 6 years ago

Maybe David is able to test something for me if he is able to repro reliable?

	Vash63 Reporter
	Comment 10 • 6 years ago

Hey guys, I'm still able to reproduce. Sorry for the delay, I didn't have access to my PC for a few days.

	Vash63 Reporter
	Comment 11 • 6 years ago

And yes, I could test a custom firefox binary.

	Alex Chronopoulos [:achronop]
	Comment 12 • 6 years ago

Thanks, this is a x64 Linux build:
https://queue.taskcluster.net/v1/task/E469gmYHS9WHP3i_yNN-Sg/runs/0/artifacts/public/build/target.tar.bz2

	Vash63 Reporter
	Comment 13 • 6 years ago

I can still duplicate the issue on that build.

	Alex Chronopoulos [:achronop]
	Comment 14 • 6 years ago

Thanks for checking, can you please post the info from about:support page?

	Vash63 Reporter
	Comment 15 • 6 years ago

Support output attached.

	David Olah
	Comment 16 • 6 years ago

Alex, do you still need me to help you with the testing?

	Alex Chronopoulos [:achronop]
	Comment 17 • 6 years ago

Since Vash63 tested my built it's not necessary for you to do anything right now. If you can repro though, you could help in the future.

	Alex Chronopoulos [:achronop]
	Comment 18 • 6 years ago

I'm afraid I cannot see a clear indication of the problem. One thing we could test is to turn off the "media.cubeb.sandbox" (set to false) and try to repro. In order to do that please go to about:config page and search for this parameter, set it to false and restart the browser.

If that does not change anything I will ask you to obtain logs. Thanks!

	David Olah
	Comment 19 • 6 years ago

I also downloaded the build that you uploaded and tried the following cases:

- accessed a youtube video
- in a new tab accessed the translate link
1. write text to translate
2. copy short text multiple times
3. copy long text
Note: I tried with different youtube resolutions, even 4k.

I could not reproduce the issue in neither of the cases above, neither with media.cubeb.sandbox set to false.
I also tried on the latest Nightly 63.0a1 (2018-07-31), and didn't managed to reproduce there neither.

	Vash63 Reporter
	Comment 20 • 6 years ago

media.cubeb.sandbox doesn't appear to have any impact on it, still the same thing.

A note for testing methodology, you don't need to type anything in the translate link - simply clicking the link and displaying it on screen is enough for the audio in all tabs to get corrupted permanently until the browser is closed and then restarted. Also this isn't specific to Youtube, I just used that as an example - playing audio in Google Music, Vimeo or other sites with audio also get corrupted. The only constant is that I can only trigger it by asking Google to translate one language to another, I haven't found any other pages that trigger the browser's audio to stop working properly. And as mentioned in the initial report, this *only* occurs on the Google search pages, using translate.google.com does not cause the same problem.

Strangely, middle clicking the link and letting it stay in the background does not cause the issue - the issue occurs only once the tab is focused the first time.

Regarding comment #18, what logs would you need? Running 'firefox' from a terminal doesn't provide much in stderr or stdout that looks useful.

	Alex Chronopoulos [:achronop]
	Comment 21 • 6 years ago

So strange behavior ...

Can you please try changing another param: security.sandbox.content.level set it to 0.

Thank you for checking the logs. In order to make firefox produce more logs you need to set the following env var:
MOZ_LOG=cubeb:4,MediaStreamGraph:4,AudioStream:4
Logs will appear in your stdout, if you can copy to a file and attach here would be great.

	Vash63 Reporter
	Comment 22 • 6 years ago

Still happens. Some additional testing:

The corruption specifically seems to be causing an echo, if I pause and resume the audio playback I can tell that it is repeating the same source audio twice about a second apart, though they sound pretty different (different volumes at very least, it's pretty distorted). 

Finally, I played some audio with Steam (which uses Chromium) after bringing up the web page in Firefox and was able to duplicate it there also... so it seems that Firefox is somehow putting Pulse or alsa in a bad state. As before the issue immediately clears up when the browser is closed though.

	Alex Chronopoulos [:achronop]
	Comment 23 • 6 years ago

Sorry not a clear evident of an error in the logs too. I see the the audio starting. I see also some IPC errors but I am not  sure how to evaluate them.

One more thing to try would be to test using a fresh new (empty) profile. I see you have 2 google translate extension on your current profile. I would not expect to affect it but you never know.

	Alex Chronopoulos [:achronop]
	Comment 24 • 6 years ago

Matthew, can you have a look at this one in case you have any better idea.

	Vash63 Reporter
	Comment 25 • 6 years ago

I was able to reproduce this on a fresh profile also. I've had this issue longer than those extensions so I knew it wasn't those but this should also rule out any about:config changes.

I'm using a stock default config shipped with Arch right now. Looking over the PKGBUILD the only settings change I see is:

  sed -e '/flat-volumes/iflat-volumes = no' \
      -i etc/pulse/daemon.conf

  sed -e '/autospawn/iautospawn = no' \
      -i etc/pulse/client.conf

Which I don't think either of these settings should be problematic. 

source: https://git.archlinux.org/svntogit/packages.git/tree/trunk/PKGBUILD?h=packages/pulseaudio

Also, given that two others here were able to reproduce it I don't suspect it's an issue with my pulse config but I'll try toggling these back to default and report back if that fixes it.

	Matthew Gregan [:kinetik]
	Comment 26 • 6 years ago

(In reply to Vash63 from comment #20)
> media.cubeb.sandbox doesn't appear to have any impact on it, still the same
> thing.

Just to clarify, did you restart Firefox after changing this pref?  It requires a restart to take effect.

Which version of Firefox were you using to produce the fflog.txt file in comment #22?

Can you also try setting the media.cubeb.backend pref (you'll need to create it, it doesn't exist by default) to "pulse", restart, and see if the issue is still present?  You can delete the pref safely after testing.

	Matthew Gregan [:kinetik]
	Comment 27 • 6 years ago

(In reply to Matthew Gregan [:kinetik] from comment #26)
> Which version of Firefox were you using to produce the fflog.txt file in
> comment #22?

It looks like it must've been 61? If you could retry the logging with a current Nightly that might be useful.

[Parent 30463: Unnamed thread 0x7f0822b40700]: E/cubeb media/libcubeb/cubeb-pulse-rs/src/backend/stream.rsattempt to divide by zero:51: Requested buffer attributes maxlength {}, tlength {}, prebuf {}, minreq {}, fragsize {}
[Parent 30463: Unnamed thread 0x7f0822b40700]: E/cubeb media/libcubeb/cubeb-pulse-rs/src/backend/stream.rsattempt to divide by zero:51: Output buffer attributes maxlength {}, tlength {}, prebuf {}, minreq {}, fragsize {}

The logging in cubeb-rs is fixed in Nightly, so we should get actual values instead of {} for these messages.

I'm suspicious about the "attempt to divide by zero" messages there too, but it's not clear where they're originating from.

	Vash63 Reporter
	Comment 28 • 6 years ago

The initial log was from the build provided in this thread. I've made a new one with the latest nightly build, this was with media.cubeb.backend = "pulse" and the default security.sandbox.content.level = 0. Strangely, I noticed the AudioStream init lines go when I started playing music on play.google.com, but *zero* lines logged when I opened the page on Google's search results page that triggers the issue. Whatever that page does doesn't seem to log with these flags.

And yes, I have restarted Firefox after every pref change when testing.

	Alex Chronopoulos [:achronop]
	Comment 29 • 6 years ago

I am afraid logs are not the expected and it is not your fault. We haven't clarified that you need to have both "media.cubeb.sandbox" = false and media.cubeb.backend = "pulse" in order to get the desired result (always restart). Sorry for the inconvenience!

	Vash63 Reporter
	Comment 30 • 6 years ago

Okay, new one is uploaded. I did notice this time when opening up the Google Translate window it added one extra line, but not any different than the one when I started the app or song playback:

[Child 15225: Main Thread]: I/cubeb media.cubeb.sandbox: false

pid 15225's creation is when the audio became garbled. The pipe errors didn't come up until I closed the tab and aren't related.

	Matthew Gregan [:kinetik]
	Comment 31 • 6 years ago

Thanks for the logs.  It's not clear what's going on from what we can see.  Would you mind also attaching PulseAudio verbose logs (instructions here: https://wiki.ubuntu.com/PulseAudio/Log) - that might allows us to see what's changing in the PA server around the time the process creation is logged and the audio becomes corrupted.

	Vash63 Reporter
	Comment 32 • 6 years ago

Okay, new log attached. It's started by a systemd user service so the formatting is a bit ugly after journalctl parsed it (couldn't get it to boot with just the 'pulseaudio' command, was still being autostarted). 

It's pretty difficult for me to follow, but I do see a lot of 'rewinds' being requested that seem potentially dangerous. The audible corruption *is* a heavily distorted repeat about 100ms later (though both the repeat and the original are distorted).

	Matthew Gregan [:kinetik]
	Comment 33 • 6 years ago

Sorry, I didn't see your response until just now.  So it looks like Firefox's media code (media.name = AudioStream, application.name = Nightly) created a stream for playback at 14:15:42 and behaves normally for ~8 seconds and then something else (media.name = playback, application.name = speech-dispatcher) creates a stream at 14:15:50 and requests an incredibly low latency:

Aug 16 14:15:50 vashnix pulseaudio[20200]: (  20.866|   0.000) D: [pulseaudio] protocol-native.c: Requested latency=0.29 ms, Received latency=0.50 ms

...after which, PulseAudio's server fails to work correctly until it's restarted (under-running and rewinding to recover).  That's an unrealistically low latency to request, but I'm also not sure why the PA server honours it since there's not much chance it'll work correctly.

There are a bunch more connections from "speech-dispatcher" made around the same time.

I'd guess the Google results page is using the Web Speech API, which triggers usage of libspeechd via SpeechDispatcherService (https://searchfox.org/mozilla-central/source/dom/media/webspeech/synth/speechd/SpeechDispatcherService.cpp).  It doesn't look like we pass any latency-related parameters to libspeechd, so I suspect a configuration issue with libspeechd at the Linux distro level, perhaps?  I see similar sounding problems reported on Arch before, although with no clear resolution: https://bbs.archlinux.org/viewtopic.php?id=215987

I'll needinfo Eitan, who implemented this, in case he has any ideas.

	Matthew Gregan [:kinetik]
	Comment 34 • 6 years ago

Forgot to mention: to test the theory that libspeechd via the Web Speech API is involved, you could try setting the pref media.webspeech.synth.enabled to false and see if the problem is still reproducible.

	Matthew Gregan [:kinetik]
	Comment 35 • 6 years ago

FWIW, it looks like libspeechd/speech-dispatcher behaves the same way on my Fedora 27 setup (i.e. requesting an unusually small latency), but it doesn't cause the PA server to underrun - so possibly the difference is at the PA level or below (hardware accepting different params?).

	Vash63 Reporter
	Comment 36 • 6 years ago

Yes! I can confirm that media.webspeech.synth.enabled toggled to 'false' fixes the issue for me. For my purposes that's all I'm going to be needing as I don't even use the text to speech part, so this is great.

And for what it's worth I don't _remember_ this happening with my old motherboard, so this definitely might be sound definitely vary by hardware/driver.

	Matthew Gregan [:kinetik]
	Comment 37 • 6 years ago

Filed a bug against speech-dispatcher: https://github.com/brailcom/speechd/issues/45

	Eitan Isaacson [:eeejay]
	Comment 38 • 6 years ago

Thanks Matthew for debugging this.

speech dispatcher uses a low latency because it is designed for screen reader use.

Maybe a longer term goal would be to not use speech dispatcher on Linux, but maybe espeak directly. It would give us a few more advantages like concurrent speech (instead of a single queue), word boundary events, and bugs like this.

Something to think about.

	Alex Chronopoulos [:achronop]
	Comment 39 • 6 years ago

That was a great finding Matthew thanks a lot. Do you know which component/person is the best to own this bug?

	Matthew Gregan [:kinetik]
	Comment 40 • 6 years ago

(In reply to Alex Chronopoulos [:achronop] from comment #39)
> That was a great finding Matthew thanks a lot. Do you know which
> component/person is the best to own this bug?

It's triggered by our use of speechd, so I guess Web Speech is a better component than Audio/Video: Playback, but the actual bug is not in Gecko code, so the best we could do is find a workaround (if that's possible).

It'd be great if the owners of the Web Speech component could work with upstream to resolve this; the bug I filed against speechd hasn't been touched for nearly a month now.  Eitan, is that you or can you point us to a suitable owner for this issue?

	Eitan Isaacson [:eeejay]
	Comment 41 • 6 years ago

Sorry, I have no pull here. I think we need to port this stuff away from speech dispatcher. It is highly specialized for screen readers. I opened a bug 1496122 for this.