469635 - ALSA error messages from esound daemon on Linux build machines

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[cajbir (:cajbir)]

The landing of bug 419275 is causing random oranges on Linux tinderboxes:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1229140245.1229142959.23926.gz
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1229322185.1229324135.13138.gz

The errors seem to be libcanberra causing alsa to report errors caused by lack of a sound card in the tinderbox machine.

These errors are similar to ones I use to get in the video code that used the
libsydneyaudio alsa backend. The alsa library outputs error messages in a
'chatty' fashion and we had to turn them off in a change to libsydneyaudio.

Comment 1

[Michael Ventnor]

Attachment: Patch

libcanberra only provides an API for backends, not actual device detection. The only way I see to solve this is to dlopen ALSA and set a blank error handler like we do for sydney audio.

Comment 2

[Robert O'Callahan (:roc) (email my personal email if necessary)]

+    if (!libasound) {
+        libasound = PR_LoadLibrary("libasound.so.2");
+        if (libasound) {
+            snd_lib_error_set_handler_fn snd_lib_error_set_handler =
+                 (snd_lib_error_set_handler_fn) PR_FindFunctionSymbol(libasound, "snd_lib_error_set_handler");
+            if (snd_lib_error_set_handler) {
+                snd_lib_error_set_handler(quiet_error_handler);
+            } else {
+                PR_UnloadLibrary(libasound);
+                libasound = nsnull;
             }
         }

Can't we unconditionally unload the library here, after we've called the function we care about?

Comment 3

[Michael Ventnor]

(In reply to comment #2)
> Can't we unconditionally unload the library here, after we've called the
> function we care about?

doublec says that once we unload the library we risk losing that change.

Comment 4

[cajbir (:cajbir)]

If you set the error handler then unload the shared library, I suspect that change would be lost unless we have loaded it already for some other reason (ie. libcanberra loaded it, or we're linked against it for video/audio support). I'm not 100% sure though.

Comment 5

[Robert O'Callahan (:roc) (email my personal email if necessary)]

I'm hoping that something we depend on has linked against it, yes. If not, then it doesn't really matter what we do here, right?

Comment 6

[Michael Ventnor]

Attachment: Patch 2

Now that I think about it, considering this is only necessary if ALSA is the canberra backend then this may still work.

Comment 7

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Pushed bb18fee38c6a to trunk.

Comment 8

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

this build on changeset 79136a417a3a:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1229506263.1229508801.972.gz
still shows errors:
ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:3947:(snd_config_expand) Evaluate error: No such device
ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:3947:(snd_config_expand) Evaluate error: No such device
ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:3947:(snd_config_expand) Evaluate error: No such device

is this expected?

Comment 9

[Robert O'Callahan (:roc) (email my personal email if necessary)]

I haven't backed out the patch, but it didn't work. The build logs still show these messages.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1229500040.1229503150.15781.gz#err0

Comment 10

[cajbir (:cajbir)]

Is it because of the unloading of the library after making the call? Easy to test locally by disabling the sound card - or run in a VM with no sound hardware set.

Comment 11

[Michael Ventnor]

Attachment: Patch 3

I tested this patch by removing my sound module and yes, it indeed works.

Comment 12

[Michael Ventnor]

This patch is applied on top of patch 2, seeing as patch 2 wasn't backed out.

Comment 13

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Pushed d92586bc82f6 to trunk

Comment 14

[Robert O'Callahan (:roc) (email my personal email if necessary)]

This patch didn't work either, the messages are still showing up:
http://tinderbox.mozilla.org/showlog.cgi?tree=Firefox&errorparser=unittest&logfile=1229565429.1229568735.19169.gz&buildtime=1229565429&buildname=Linux%20mozilla-central%20moz2-linux-slave07%20dep%20unit%20test&fulltext=1#err2

Comment 15

[Michael Ventnor]

I'm defeated then, since I get nothing at all on my box when I disable my sound card and run the mochitests that cause these messages.

I'm wondering what the tests run that call a system sound. Do these builds also have special compile options?

Comment 16

[Michael Ventnor]

And I verified that the dummy error-handling function was called when I added a printf into it.

Comment 17

[Michael Ventnor]

Attachment: Patch 4

roc gave me a suggestion for a new strategy; the library may not be given that file name on the tinderboxes so we should lookup via symbol instead of filename.

Comment 18

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Pushed that as 545936b5bbe4. I'll leave the bug open though until we're sure it's fixed :-)

Comment 19

[Matthew Gregan [:kinetik]]

Still happening:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1229574617.1229577197.5534.gz

I noticed that there are two error handlers in libasound (one seems to be for internal use).  Depending on how the library is built, you can only override one of them using snd_lib_error_set_handler:

int snd_lib_error_set_handler(snd_lib_error_handler_t handler)
{                                        
        snd_lib_error = handler == NULL ? snd_lib_error_default : handler;
#ifndef NDEBUG                                
        if (snd_lib_error != snd_lib_error_default)
                snd_err_msg = snd_lib_error;
#endif                                
        return 0;                     
}

I booted up my CentOS 5 reference VM and confirmed via disassembly that snd_lib_error_set_handler in libasound.so.2 is compiled such that it allows both handlers to be overridden.  From a quick scan of the errors we're seeing, they're all logged via the snd_lib_error handler anyway.

Do the test machines have libcanberra installed?  My reference VM doesn't, and I haven't done anything with it since I downloaded it from ftp.mozilla.org.  If the test machines don't, then I wonder if this is being caused through using libesd (which does exist and links against libasound).  Maybe just moving the snd_lib_error_set_handler call above the load and initialization of libesd would be sufficient to silence these warnings.

Comment 21

[Nick Thomas [:nthomas] (UTC+12)]

(In reply to comment #19)
> Do the test machines have libcanberra installed?  My reference VM doesn't, and
> I haven't done anything with it since I downloaded it from ftp.mozilla.org. 

It appears not based on lack of matches to /usr/lib/libcan*. The downloadable reference VM will be slightly behind the current state of the art, it'll be one of the version here
  https://wiki.mozilla.org/ReferencePlatforms/Linux-CentOS-5.0
but there's nothing there modifying sound libraries.

Comment 22

[(not currently active) Ted Mielczarek]

Anyone want to give this another shot in light of comment 19 and comment 21? These extra error messages make it a lot harder to see real test failures.

Comment 23

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Matthew, can you create a patch for this? Even if you can't reproduce the problem, we can try to land it and see if it fixes things.

Comment 24

[Matthew Gregan [:kinetik]]

Attachment: patch v5

Not sure this'll work, but let's see.  Move the call to snd_lib_error_set_handler above the opening of ESD.  Add some debug logging in a bunch of places to help see what's going on.  We can remove the logging after one cycle on the build machines.

Comment 25

[Matthew Gregan [:kinetik]]

Attachment: revert debug logging

If patch v5 is successful at suppressing the errors we're seeing on the test machines, this patch can be applied to remove the debug logging I added in patch v5.  No need for review because it's just a straight revert of the logging parts of patch v5.

Comment 26

[Karl Tomlinson (:karlt)]

Comment on attachment 363047 [details] [diff] [review]
patch v5

This was pushed

http://hg.mozilla.org/mozilla-central/rev/03b4b372bacc

but had no effect and so was backed out.

Comment 27

[Karl Tomlinson (:karlt)]

The logging produced:

asound_hack: 1 lib_err 442ab40, err_msg 442a9f0
asound_hack: quiet_error_handler installed 2 lib_err 157e0c4, err_msg 157e0c4
asound_hack: 3 lib_err 157e0c4, err_msg 157e0c4, can (nil)
ALSA lib confmisc.c:670:(snd_func_card_driver) cannot find card '0'
NEXT ERROR ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib confmisc.c:391:(snd_func_concat) error evaluating strings
NEXT ERROR ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib confmisc.c:1070:(snd_func_refer) error evaluating name
NEXT ERROR ALSA lib conf.c:3479:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:3947:(snd_config_expand) Evaluate error: No such device
ALSA lib pcm.c:2143:(snd_pcm_open_noupdate) Unknown PCM default

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1235101197.1235107655.3423.gz#err0

Comment 28

[Matthew Gregan [:kinetik]]

Thanks Karl.  The extra logging at least proves that we successfully install our quiet error handler before the messages are logged (and that they're still logged despite that).  It also confirms that we're not finding libcanberra, so we can probably rule that out of the equation.

The errors are logged when attempting to open a sound device.  The last error (from snd_pcm_open_noupdate) is logged when the configuration phase has failed.

Comment 29

[Matthew Gregan [:kinetik]]

Uh, I'm sure I was going somewhere with the last paragraph of comment #28, but I don't know where.

Anyway, I spent this evening setting up a build environment on my reference VM and I can now reproduce this locally.

It turns out that it's the call to esd_open_sound that's causing the ALSA errors, but they're not logged by any code executing in our process.  esd_open_sound will spawn a (local, temporary) copy of the ESD daemon if there isn't a daemon already running.  The daemon process attempts to initialize ALSA and ends up printing the messages we're seeing.

Later versions of ESD (starting with 0.2.39, see http://bugzilla.gnome.org/buglist.cgi?query=528718) call snd_lib_error_set_handler to suppress error logging.

I'm not sure why we only just started noticing this.  Maybe something was installed on the build hosts that pulled in ESD?

I'm not sure why we call esd_open_sound anyway--the esdref we get back is never used again (except to close ESD again), and the message about it being needed for streams but not playing sounds is curious.

Removing the call wouldn't help, anyway, because we'll eventually call esd_play_stream (which calls esd_open_sound internally).  But removing both of those and just using esd_audio_open (and calling snd_lib_error_set_handler ourselves beforehand) would work, since that calls into the audio backend directly, without spawning a daemon.

Removing ESD from the build machines would stop the errors, but also causes libmozgnome.so (which is linked to libesd.so.0) to fail to load.

Also, after calling esd_open_sound we should be testing for esdref < 0, not !esdref, since it's returning a file descriptor.

Comment 30

[Matthew Gregan [:kinetik]]

It sounds like we need to call esd_open_sound to initialize the library, but it's hard to tell, the docs (http://www.tux.org/~ricdude/dbdocs/esound_api.html) are not particularly enlightening.  Given that esd_play_stream calls it internally anyway, I'm not convinced.  Trawling through CVS history doesn't shed much light on the situation, either.

CentOS is still shipping ESD 0.2.36 in 5.1, so we can't easily pull an updated package to solve this.

It'd be bad to always use esd_audio_open, since then we'd never use an existing ESD daemon, and might run into problems sharing the audio hardware that would've been avoided had we used the daemon.

We could work around it on the build machines: rename /usr/bin/esd to /usr/bin/esd.real and put an esd script in place that execs esd.real with stderr redirected.

Comment 31

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Overkill for this bug perhaps, but could we remove the use of ESD completely by refactoring our content/media Wave code and reimplementing nsSound on top of that?

Comment 32

[Matthew Gregan [:kinetik]]

Yup, I think we should do that eventually.  My one concern would be that simple sound playback might break for some users since ESD supports more backends (and, I think, can be configured to use different backends without a recompile) than libsydneyaudio.  Obviously the same users wouldn't have working audio with the new video/audio stuff, so we'd want to fix it anyway, which might not make this much of a concern.

Comment 33

[Robert O'Callahan (:roc) (email my personal email if necessary)]

I'm not sure what our best option is, short of that.

Comment 34

[Matthew Gregan [:kinetik]]

Given that this is only a problem on the build machines, I think the best option is silencing ESD on those machines:

% mv /usr/bin/esd /usr/bin/esd.real
% cat > /usr/bin/esd
#! /bin/sh
exec /usr/bin/esd.real "$@" 2>/dev/null
^D
% chmod +x /usr/bin/esd

I've tested that on my reference VM and it does the trick.

Comment 35

[Matthew Gregan [:kinetik]]

Attachment: remove asound hackery, fix esd_sound_open error test

This fixes the esd_sound_open error handling case, and removes all of the libasound hackery now that we know it's unnecessary.

Comment 36

[Matthew Gregan [:kinetik]]

Pushed http://hg.mozilla.org/mozilla-central/rev/57ace2f00d62.

Retitled and reassigning to build machine component for someone to look at comment #30 and comment #34.

Comment 37

[Matthew Gregan [:kinetik]]

I backed out that patch (http://hg.mozilla.org/mozilla-central/rev/c984d8c6bca4) for two reasons.  There was a mochitest timeout (which shouldn't be related), and it made the ALSA error logging even worse (from 4 sets of errors to 8 pages).  Without the quiet handler installed, end up seeing a set of errors every time we go through the non-daemon ESD fallback path as well.

So we either need a combination of the quiet handler installed and ESD silenced per comment #34, or an upgraded ESD on the build machines.  Or give up on the ESD approach and spent the time converting nsSound to use the Wave decoder as Robert suggested in comment #31.

Comment 38

[[e-mail] (:bhearsum)]

I take it that the nsSound route isn't the preferred one?

Comment 39

[Robert O'Callahan (:roc) (email my personal email if necessary)]

We should do both IMHO, but replacing nsSound is a fair bit of work that wasn't on our list of things to do in the 1.9.1 timeframe.

Comment 40

[[e-mail] (:bhearsum)]

Okay, in the meantime I'll go ahead and deploy the esd wrapper in our pool.

Comment 41

[[e-mail] (:bhearsum)]

Attachment: esd script, in easily downloadable form

Comment 42

[[e-mail] (:bhearsum)]

I've deployed the esd wrapper on all of the 1.9.1, tm, and m-c slave as well as the try slaves. Only place left is the ref platform itself.

Roc/Matthew, do you want to take this bug back or file a new one for nsSound?

Comment 43

[Matthew Gregan [:kinetik]]

Thanks Ben!

I've filed a new bug for nsSound: bug 479822.

Comment 44

[[e-mail] (:bhearsum)]

Alright, this has been deployed on the ref platform as well. We're all done here.