Bug 49681 - system.pa crashes if auth-anonymous=1 is used with module-native-protocol-tcp
Summary: system.pa crashes if auth-anonymous=1 is used with module-native-protocol-tcp
Status: NEW
Alias: None
Product: PulseAudio
Classification: Unclassified
Component: modules (show other bugs)
Version: unspecified
Hardware: x86 (IA32) Linux (All)
: medium normal
Assignee: pulseaudio-bugs
QA Contact: pulseaudio-bugs
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-05-09 03:15 UTC by Martin-Éric Racine
Modified: 2014-10-25 11:41 UTC (History)
4 users (show)

See Also:
i915 platform:
i915 features:


Attachments
debug log on the sound server (120.24 KB, text/plain)
2012-05-09 03:15 UTC, Martin-Éric Racine
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Martin-Éric Racine 2012-05-09 03:15:18 UTC
Created attachment 61273 [details]
debug log on the sound server

USAGE CASE

I have setup a small embedded device to act as a sound server for my local network. It outputs sound sent by my laptop to speakers connected into the embedded device. Both PA devices run the same versions.

PROBLEM
Since cookie exchanges won't work because the PA daemon stores its cookie into /var/run, and because this runs on my home LAN, I have decided to use auth-anonymous. Yet, the sound server crashes as soon as I enable "Make remote native PA sinks available to the local computer" in the laptop's paprefs.
Comment 1 Martin-Éric Racine 2012-05-16 02:01:28 UTC
Further testing using the command below shows that remote speakers indeed work as intended:

$ LC_ALL=C PULSE_SERVER=geode.lan speaker-test -c2 -twav

What instead seems to be the source of the problem is that the tunnel created by paprefs on the client host, whenever "Make remote native audio sinks available localy" is selected, is what crashes the remote host's PA server.
Comment 2 Martin-Éric Racine 2012-06-01 02:00:21 UTC
Instructions on how to debug the exact cause of this tunnel resulting in a collapse of the remove sink's server are welcome.
Comment 3 Tanu Kaskinen 2012-06-01 03:32:30 UTC
Is the crash a segfault or an assertion crash or something else? At least the attached log doesn't show any assertion message... If it's a segfault, please install the debug symbols and run pulseaudio under gdb as instructed at http://www.freedesktop.org/wiki/Software/PulseAudio/Documentation/User/Community
Comment 4 Martin-Éric Racine 2012-06-01 03:53:38 UTC
I: [alsa-source] alsa-source.c: Overrun!
I: [alsa-source] alsa-source.c: Increasing minimal latency to 1,00 ms
D: [alsa-source] alsa-source.c: latency set to 24,99ms
D: [alsa-source] alsa-source.c: hwbuf_unused=61132
D: [alsa-source] alsa-source.c: setting avail_min=443

Program received signal SIGILL, Illegal instruction.
[Switching to Thread 0xb30eeb70 (LWP 4689)]
0xb1fdf031 in ?? ()
(gdb) bt
#0  0xb1fdf031 in ?? ()
#1  0x00000157 in ?? ()
(gdb) 


Yes, all PA debugging symbols are installed. If the above results are not precise enough, please further document what's expected and how to achieve the result.
Comment 5 Martin-Éric Racine 2012-06-01 06:20:34 UTC
$ sudo LD_BIND_NOW=1 gdb pulseaudio
GNU gdb (GDB) 7.4.1-debian
Copyright (C) 2012 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "i486-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/bin/pulseaudio...Reading symbols from /usr/lib/debug/usr/bin/pulseaudio...done.
done.
(gdb) run --system --disallow-exit --disallow-module-loading --log-target=syslog --high-priority -vvvvv
Starting program: /usr/bin/pulseaudio --system --disallow-exit --disallow-module-loading --log-target=syslog --high-priority -vvvvv
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/i386-linux-gnu/libthread_db.so.1".
[New Thread 0xb30eeb70 (LWP 11959)]
[New Thread 0xb28deb70 (LWP 11960)]
WARNING: Unhandled message: interface=(null), path=(null), member=(null)
WARNING: Unhandled message: interface=(null), path=(null), member=(null)

Program received signal SIGILL, Illegal instruction.
[Switching to Thread 0xb30eeb70 (LWP 11959)]
0xb1fdf031 in ?? ()
(gdb) bt
#0  0xb1fdf031 in ?? ()
#1  0x000004ac in ?? ()
(gdb)
Comment 6 Martin-Éric Racine 2012-06-01 06:22:20 UTC
$ dpkg -l | grep dbg | awk '{print $2}' | cut -d: -f1 
avahi-dbg
libasound2-dbg
libc6-dbg
libcanberra-pulse-dbg
libgcc1-dbg
libice6-dbg
liborc-0.4-0-dbg
libpulse-mainloop-glib0-dbg
libpulse0-dbg
libsm6-dbg
libtdb1-dbg
libx11-6-dbg
libx11-xcb1-dbg
libxcb1-dbg
pulseaudio-dbg
pulseaudio-module-bluetooth-dbg
pulseaudio-module-gconf-dbg
pulseaudio-module-jack-dbg
pulseaudio-module-x11-dbg
pulseaudio-module-zeroconf-dbg
pulseaudio-utils-dbg
valgrind-dbg
Comment 7 Tanu Kaskinen 2012-06-01 08:43:36 UTC
(In reply to comment #5)
> $ sudo LD_BIND_NOW=1 gdb pulseaudio
> GNU gdb (GDB) 7.4.1-debian
> Copyright (C) 2012 Free Software Foundation, Inc.
> License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
> This is free software: you are free to change and redistribute it.
> There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
> and "show warranty" for details.
> This GDB was configured as "i486-linux-gnu".
> For bug reporting instructions, please see:
> <http://www.gnu.org/software/gdb/bugs/>...
> Reading symbols from /usr/bin/pulseaudio...Reading symbols from
> /usr/lib/debug/usr/bin/pulseaudio...done.
> done.
> (gdb) run --system --disallow-exit --disallow-module-loading
> --log-target=syslog --high-priority -vvvvv
> Starting program: /usr/bin/pulseaudio --system --disallow-exit
> --disallow-module-loading --log-target=syslog --high-priority -vvvvv
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library "/lib/i386-linux-gnu/libthread_db.so.1".
> [New Thread 0xb30eeb70 (LWP 11959)]
> [New Thread 0xb28deb70 (LWP 11960)]
> WARNING: Unhandled message: interface=(null), path=(null), member=(null)
> WARNING: Unhandled message: interface=(null), path=(null), member=(null)

I wonder what these warnings are... They are not coming directly from Pulseaudio at least - I don't know if they from gdb or from some library, but it seems to be related to D-Bus. I don't think gdb uses D-Bus for anything, so I guess they are from some library. Do you get these always?

> 
> Program received signal SIGILL, Illegal instruction.
> [Switching to Thread 0xb30eeb70 (LWP 11959)]
> 0xb1fdf031 in ?? ()

I believe this is the program counter, and it seems to point to some random place. Maybe a corrupted function pointer? Whatever it is, the stack has become invalid, so the backtrace is useless.

It's impossible to say where the crash is happening. I'd debug this by adding debug prints until I find the exact place that crashes. Is the end of the log always the same, that is, does the log always end with "D: [alsa-source] alsa-source.c: setting avail_min=443"? If it's always the same, then start by adding debug prints after the code that prints that.

Since you'll have to compile pulseaudio yourself, try the latest development version. With luck this is already fixed.
Comment 8 Martin-Éric Racine 2012-06-01 09:13:14 UTC
Actually, this issue was introduced with 1.1 and is unresolved as of 2.0
Comment 9 Martin-Éric Racine 2012-06-01 10:28:42 UTC
Here's the output of a more complete backtrace produced with "thread apply all bt":



D: [alsa-source] source.c: Volume not changing
D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
D: [pulseaudio] protocol-dbus.c: Interface org.PulseAudio.Core1.Stream added for object /org/pulseaudio/core1/record_stream0
D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
D: [alsa-sink] alsa-sink.c: Requested to rewind 65536 bytes.
D: [alsa-sink] alsa-sink.c: Limited to 4304 bytes.
D: [alsa-sink] alsa-sink.c: before: 1076
D: [alsa-sink] alsa-sink.c: after: 1076
D: [alsa-sink] alsa-sink.c: Rewound 4304 bytes.
D: [alsa-sink] sink.c: Processing rewind...
D: [alsa-sink] sink.c: latency = 1026
D: [alsa-sink] sink-input.c: Have to rewind 4304 bytes on render memblockq.
D: [alsa-sink] source.c: Processing rewind...

Program received signal SIGILL, Illegal instruction.
[Switching to Thread 0xb30eeb70 (LWP 3712)]
0xb1fdf031 in ?? ()
(gdb) thread apply all bt

Thread 3 (Thread 0xb28deb70 (LWP 3713)):
#0  0xb7d4c26b in ppoll (fds=0x806cc18, nfds=4, timeout=0xb28de218, sigmask=sigmask@entry=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:58
#1  0xb7f679aa in pa_rtpoll_run (p=0x80829c8, wait_op=wait_op@entry=true) at pulsecore/rtpoll.c:314
#2  0xb3132d92 in thread_func (userdata=0x8076c38) at modules/alsa/alsa-source.c:1513
#3  0xb7f142fa in internal_thread_func (userdata=0x80853d8) at pulsecore/thread-posix.c:83
#4  0xb7dd9954 in start_thread (arg=0xb28deb70) at pthread_create.c:304
#5  0xb7d599fe in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 2 (Thread 0xb30eeb70 (LWP 3712)):
#0  0xb1fdf031 in ?? ()
#1  0x0000048c in ?? ()

Thread 1 (Thread 0xb75c3700 (LWP 3709)):
#0  0xb7de0cd1 in write () at ../sysdeps/unix/syscall-template.S:82
#1  0xb7ee5020 in pa_write (fd=11, buf=buf@entry=0xbffff288, count=count@entry=8, type=type@entry=0x0) at pulsecore/core-util.c:418
#2  0xb7f5ac6f in pa_fdsem_post (f=0x806d9f8) at pulsecore/fdsem.c:199
#3  0xb7f46962 in push (l=0x8090518, l@entry=0x0, p=p@entry=0x80ff8f0, wait_op=false) at pulsecore/asyncq.c:162
#4  0xb7f46d1f in pa_asyncq_push (l=0x0, l@entry=0x8090518, p=p@entry=0x80ff8f0, wait_op=wait_op@entry=false) at pulsecore/asyncq.c:194
#5  0xb7f46de3 in pa_asyncq_post (l=0x8090518, p=p@entry=0x80ff8f0) at pulsecore/asyncq.c:204
#6  0xb7f458b3 in pa_asyncmsgq_post (a=0x806c500, object=object@entry=0x8100220, code=code@entry=7, userdata=userdata@entry=0x0, offset=0, 
    chunk=chunk@entry=0xbffff444, free_cb=free_cb@entry=0) at pulsecore/asyncmsgq.c:137
#7  0xb20cb1db in pstream_memblock_callback (p=p@entry=0x80fd648, channel=channel@entry=0, offset=0, seek=seek@entry=PA_SEEK_RELATIVE, 
    chunk=chunk@entry=0xbffff444, userdata=0x8082928) at pulsecore/protocol-native.c:4779
#8  0xb7f036a4 in do_read (p=0x80fd648) at pulsecore/pstream.c:784
#9  do_something (p=0x80fd648) at pulsecore/pstream.c:180
#10 0xb7eee738 in callback (m=m@entry=0x80621a8, e=e@entry=0x81075d0, fd=21, f=PA_IO_EVENT_INPUT, userdata=userdata@entry=0x8103918)
    at pulsecore/iochannel.c:160
#11 0xb7ea0e5c in dispatch_pollfds (m=0x8062168) at pulse/mainloop.c:677
#12 pa_mainloop_dispatch (m=m@entry=0x8062168) at pulse/mainloop.c:927
#13 0xb7ea1305 in pa_mainloop_iterate (m=m@entry=0x8062168, block=block@entry=1, retval=retval@entry=0xbffff5ec) at pulse/mainloop.c:958
#14 0xb7ea13d4 in pa_mainloop_run (m=m@entry=0x8062168, retval=retval@entry=0xbffff5ec) at pulse/mainloop.c:973
#15 0x0804e32a in main (argc=6, argv=0xbffff7d4) at daemon/main.c:1135
(gdb)
Comment 10 Tanu Kaskinen 2012-06-01 11:13:48 UTC
At least in the case of the last backtrace, the main thread has just sent a chunk of audio to the alsa sink's IO thread (the SINK_INPUT_MESSAGE_POST_DATA message), and is waiting for that operation to finish. I'd start narrowing down the problem by adding debug prints in the SINK_INPUT_MESSAGE_POST_DATA handling section of the sink_input_process_msg() function in src/pulsecore/protocol-native.c.

Or do bisecting with git, if this is a regression as you think.
Comment 11 Martin-Éric Racine 2012-07-17 13:46:48 UTC
I would call it a regression because this used to work rock-solid until PA 1.0, because less reliable starting with 1.1 and no longer works since 2.0 came.
Comment 12 Martin-Éric Racine 2012-07-17 15:55:14 UTC
It should also be noted that while 'speaker-test' works from command line as in comment 1, 'PULSE_SERVER=geode.lan rhythmbox' however makes the remote sink crash immediately as previously reported.
Comment 13 Martin-Éric Racine 2012-07-18 11:24:45 UTC
Two additional observations:

1) Whenever manually toggling the gconf key to enable loading of 'module-zeroconf-discover' in the local host's gconf-editor, gconf-editor crashes.

2) Trying to manually load 'module-zeroconf-discover' on the local host using 'pacmd' produces the following in syslog:

Jul 18 14:14:06 henna pulseaudio[14626]: [pulseaudio] module-tunnel.c: Failed to create sink.
Jul 18 14:14:06 henna pulseaudio[14626]: [pulseaudio] module.c: Failed to load module "module-tunnel-sink" (argument: "server=[172.16.1.1]:4713 sink=alsa_output.pci-0000_00_0f.3.analog-stereo format=s16le channels=2 rate=44100 sink_name=tunnel.geode.local.alsa_output.pci-0000_00_0f.3.analog-stereo channel_map=front-left,front-right"): initialization failed.
Jul 18 14:14:06 henna pulseaudio[14626]: [pulseaudio] module-tunnel.c: Stream died.
Jul 18 14:14:06 henna pulseaudio[14626]: [pulseaudio] module-tunnel.c: Failed to create source.
Jul 18 14:14:06 henna pulseaudio[14626]: [pulseaudio] module.c: Failed to load module "module-tunnel-source" (argument: "server=[172.16.1.1]:4713 source=alsa_input.pci-0000_00_0f.3.analog-stereo format=s16le channels=2 rate=44100 source_name=tunnel.geode.local.alsa_input.pci-0000_00_0f.3.analog-stereo channel_map=front-left,front-right"): initialization failed.
Jul 18 14:14:06 henna pulseaudio[14626]: [pulseaudio] module-tunnel.c: Stream died.
Comment 14 Martin-Éric Racine 2012-07-22 17:00:22 UTC
With PA 2.1, enabling the remote native sink detection in the client's paprefs doesn't crash the remote server. Hurray!

However, initialization of the tunnel fails on the client side:

Jul 22 19:54:49 henna pulseaudio[15144]: [pulseaudio] module-tunnel.c: Failed to create source.
Jul 22 19:54:49 henna pulseaudio[15144]: [pulseaudio] module.c: Failed to load module "module-tunnel-source" (argument: "server=[fe80::240:caff:fe9d:f050]:4713 source=alsa_input.pci-0000_00_0f.3.analog-stereo format=s16le channels=2 rate=44100 source_name=tunnel.geode.local.alsa_input.pci-0000_00_0f.3.analog-stereo channel_map=front-left,front-right"): initialization failed.
Jul 22 19:54:49 henna pulseaudio[15144]: [pulseaudio] module-tunnel.c: Failed to create sink.
Jul 22 19:54:49 henna pulseaudio[15144]: [pulseaudio] module.c: Failed to load module "module-tunnel-sink" (argument: "server=[fe80::240:caff:fe9d:f050]:4713 sink=alsa_output.pci-0000_00_0f.3.analog-stereo format=s16le channels=2 rate=44100 sink_name=tunnel.geode.local.alsa_output.pci-0000_00_0f.3.analog-stereo channel_map=front-left,front-right"): initialization failed.
Jul 22 19:54:49 henna pulseaudio[15144]: [pulseaudio] module-tunnel.c: Stream died.
Jul 22 19:54:49 henna pulseaudio[15144]: [pulseaudio] module-tunnel.c: Stream died.

On the remote sink, syslog reports an endless series of these, whenever the client's paprefs has native sink detection enabled:

Jul 22 19:54:46 geode pulseaudio[2080]: [pulseaudio] protocol-native.c: Denied access to client with invalid authorization data.
Comment 15 Martin-Éric Racine 2012-08-03 08:34:35 UTC
This reminds me, exactly how is the client side supposed to acquire and exchange authentication data, when the use of a remote sink is enabled via paprefs? 

That endless series of "protocol-native.c: Denied access to client with invalid authorization data." messages in the remote sink's PA log suggests a problem with how the client authenticates when a native remote sink is selected via GNOME's audio control applet.

Again, ideas on how to debug what goes wrong with this particular aspect would be welcome.
Comment 16 Martin-Éric Racine 2012-08-10 12:20:21 UTC
One interesting piece of information:

I get that SIGILL on the remote PA sink, the minute Avahi is restarted at either the client or remote end, if "detect native sinks" is enabled in the client's paprefs.
Comment 17 Martin-Éric Racine 2012-08-10 12:45:29 UTC
Or if I just let the PA daemon sit there long enough:

(gdb) run --system
The program being debugged has been started already.
Start it from the beginning? (y or n) y
Starting program: /usr/bin/pulseaudio --system
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/i386-linux-gnu/libthread_db.so.1".
process 10317 is executing new program: /usr/bin/pulseaudio
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/i386-linux-gnu/libthread_db.so.1".
W: [pulseaudio] main.c: Suoritetaan järjestelmätilassa, mutta --disallow-exit ei ole asetettuna!
W: [pulseaudio] main.c: Suoritetaan järjestelmätilassa, mutta -disallow-module-loading ei ole asetettuna!
N: [pulseaudio] main.c: Suoritetaan järjestelmätilassa, otetaan SHM-tila pakotetusti pois käytöstä.
N: [pulseaudio] main.c: Suoritetaan järjestelmätilassa, otetaan poistumisen joutenoloaika pakotetusti pois käytöstä.
W: [pulseaudio] main.c: PA:ta suoritetaan järjestelmätilassa. Näin ei luultavasti pitäisi tehdä.
W: [pulseaudio] main.c: Jos silti teet näin, on sinun vikasi jos kaikki ei toimikaan odotetusti.
W: [pulseaudio] main.c: Lisätietoja siitä, miksi järjestelmätilan käyttäminen on yleensä huono ajatus on osoitteessa http://pulseaudio.org/wiki/WhatIsWrongWithSystemMode
W: [pulseaudio] pid.c: Stale PID file, overwriting.
[New Thread 0xb30ebb70 (LWP 10318)]
[New Thread 0xb28dbb70 (LWP 10319)]

Program received signal SIGILL, Illegal instruction.
[Switching to Thread 0xb30ebb70 (LWP 10318)]
0xb201e031 in ?? ()
(gdb) bt
#0  0xb201e031 in ?? ()
#1  0x00000411 in ?? ()
(gdb) info threads
  Id   Target Id         Frame 
  3    Thread 0xb28dbb70 (LWP 10319) "alsa-source" 0xb7d4afab in ppoll (fds=0x8077f00, nfds=4, timeout=0xb28db228, 
    sigmask=sigmask@entry=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:58
* 2    Thread 0xb30ebb70 (LWP 10318) "alsa-sink" 0xb201e031 in ?? ()
  1    Thread 0xb75c0700 (LWP 10317) "pulseaudio" 0xb7ddfcd1 in write () at ../sysdeps/unix/syscall-template.S:82
(gdb)
Comment 18 Martin-Éric Racine 2012-08-10 13:16:33 UTC
I: [pulseaudio] socket-server.c: TCP connection accepted by tcpwrap.
I: [pulseaudio] client.c: Created 0 "Native client (TCP/IP client from 172.16.1.5:37096)"
I: [pulseaudio] protocol-native.c: Client authenticated anonymously.
I: [pulseaudio] socket-server.c: TCP connection accepted by tcpwrap.
I: [pulseaudio] client.c: Created 1 "Native client (TCP/IP client from 172.16.1.5:37097)"
I: [pulseaudio] protocol-native.c: Client authenticated anonymously.
I: [pulseaudio] sink-input.c: Trying to change sample rate
I: [pulseaudio] alsa-sink.c: Updating rate for device hw:0, new rate is 44100
I: [pulseaudio] sink.c: Changed sampling rate successfully
I: [pulseaudio] sink-input.c: Rate changed to 44100 Hz
I: [pulseaudio] module-stream-restore.c: Restoring volume for sink input sink-input-by-media-role:abstract.
I: [alsa-sink] alsa-sink.c: Trying resume...
I: [alsa-sink] alsa-util.c: cannot disable ALSA period wakeups
I: [alsa-sink] alsa-util.c: ALSA period wakeups were not disabled
I: [alsa-sink] alsa-sink.c: Time scheduling watermark is 20,00ms
I: [alsa-sink] alsa-sink.c: Resumed successfully...
I: [alsa-sink] alsa-sink.c: Starting playback.
I: [pulseaudio] sink-input.c: Created input 2 "alsa_output.pci-0000_00_0f.3.analog-stereo for perkelix@henna" on alsa_output.pci-0000_00_0f.3.analog-stereo with sample spec s16le 2 kan. 44100Hz and channel map front-left,front-right
I: [pulseaudio] sink-input.c:     media.name = "alsa_output.pci-0000_00_0f.3.analog-stereo for perkelix@henna"
I: [pulseaudio] sink-input.c:     media.role = "abstract"
I: [pulseaudio] sink-input.c:     application.name = "pulseaudio"
I: [pulseaudio] sink-input.c:     native-protocol.peer = "TCP/IP client from 172.16.1.5:37097"
I: [pulseaudio] sink-input.c:     native-protocol.version = "26"
I: [pulseaudio] sink-input.c:     application.id = "org.PulseAudio.PulseAudio"
I: [pulseaudio] sink-input.c:     application.version = "2.0"
I: [pulseaudio] sink-input.c:     application.process.id = "15822"
I: [pulseaudio] sink-input.c:     application.process.user = "perkelix"
I: [pulseaudio] sink-input.c:     application.process.host = "henna"
I: [pulseaudio] sink-input.c:     application.process.binary = "pulseaudio"
I: [pulseaudio] sink-input.c:     application.language = "fi_FI.utf8"
I: [pulseaudio] sink-input.c:     window.x11.display = ":0"
I: [pulseaudio] sink-input.c:     application.process.machine_id = "60f25f1639832f9c0a289bca0000000c"
I: [pulseaudio] sink-input.c:     application.process.session_id = "60f25f1639832f9c0a289bca0000000c-1344510160.104862-1484012252"
I: [pulseaudio] sink-input.c:     module-stream-restore.id = "sink-input-by-media-role:abstract"
I: [pulseaudio] protocol-native.c: Requested tlength=150,00 ms, minreq=24,99 ms
I: [pulseaudio] protocol-native.c: Final latency 174,99 ms = 100,02 ms + 2*24,99 ms + 24,99 ms
I: [alsa-source] alsa-source.c: Trying resume...
I: [alsa-source] alsa-util.c: cannot disable ALSA period wakeups
I: [alsa-source] alsa-util.c: ALSA period wakeups were not disabled
I: [alsa-source] alsa-source.c: Time scheduling watermark is 20,00ms
I: [alsa-source] alsa-source.c: Resumed successfully...
I: [alsa-source] alsa-source.c: Starting capture.
I: [pulseaudio] source-output.c: Created output 0 "alsa_input.pci-0000_00_0f.3.analog-stereo for perkelix@henna" on alsa_input.pci-0000_00_0f.3.analog-stereo with sample spec s16le 2 kan. 44100Hz and channel map front-left,front-right
I: [pulseaudio] source-output.c:     media.name = "alsa_input.pci-0000_00_0f.3.analog-stereo for perkelix@henna"
I: [pulseaudio] source-output.c:     media.role = "abstract"
I: [pulseaudio] source-output.c:     application.name = "pulseaudio"
I: [pulseaudio] source-output.c:     native-protocol.peer = "TCP/IP client from 172.16.1.5:37096"
I: [pulseaudio] source-output.c:     native-protocol.version = "26"
I: [pulseaudio] source-output.c:     application.id = "org.PulseAudio.PulseAudio"
I: [pulseaudio] source-output.c:     application.version = "2.0"
I: [pulseaudio] source-output.c:     application.process.id = "15822"
I: [pulseaudio] source-output.c:     application.process.user = "perkelix"
I: [pulseaudio] source-output.c:     application.process.host = "henna"
I: [pulseaudio] source-output.c:     application.process.binary = "pulseaudio"
I: [pulseaudio] source-output.c:     application.language = "fi_FI.utf8"
I: [pulseaudio] source-output.c:     window.x11.display = ":0"
I: [pulseaudio] source-output.c:     application.process.machine_id = "60f25f1639832f9c0a289bca0000000c"
I: [pulseaudio] source-output.c:     application.process.session_id = "60f25f1639832f9c0a289bca0000000c-1344510160.104862-1484012252"
I: [pulseaudio] source-output.c:     module-stream-restore.id = "source-output-by-media-role:abstract"
I: [pulseaudio] protocol-native.c: Final latency 49,98 ms = 24,99 ms + 24,99 ms

Program received signal SIGILL, Illegal instruction.
[Switching to Thread 0xb30ebb70 (LWP 19805)]
0xb1fdc031 in ?? ()
(gdb) info threads
  Id   Target Id         Frame 
  3    Thread 0xb28dbb70 (LWP 19806) "alsa-source" 0xb7d4afab in ppoll (fds=0x80775c8, nfds=4, timeout=0xb28db228, 
    sigmask=sigmask@entry=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:58
* 2    Thread 0xb30ebb70 (LWP 19805) "alsa-sink" 0xb1fdc031 in ?? ()
  1    Thread 0xb75c0700 (LWP 19804) "pulseaudio" 0xb7ddfcd1 in write () at ../sysdeps/unix/syscall-template.S:82
(gdb)
Comment 19 Martin-Éric Racine 2012-09-06 15:34:02 UTC
Sjoerd suggested trying once more by enabling the remote host via 'paprefs' (Enable network access to local sound device, allow other machines on the LAN to discover local sound devices, dont'require authentication) inside a normal GNOME session rather than via a daemon running in System mode. At first, nothing worked. However, after restarting Avahi, the sink suddently appeared on my client host's GNOME Volume Control's Output tab.

This seems to suggest that the real issue might be with Avahi either being started too early in the boot process or not getting the information about the new netowrk service becoming available from the PA daemon.

At least, we're getting much closer to finding the cause now.

Instructions on further debugging this issue are very welcome!
Comment 20 Martin-Éric Racine 2012-10-08 16:02:53 UTC
Upon further investigation, it indeed seems that Avahi *MUST* always be started before the PA daemon for remote sinks to work at all. Right now, this isn't the case, at least in Debian and Ubuntu packages, because the /etc/init.d/pulseaudio boot script doesn't declare Avahi as an LSB header dependency.
Comment 21 Nix 2014-05-08 19:56:46 UTC
Hello,

I have a very similar problem and I wonder if you ever managed to solve this issue. And still remember how :)

A solution or a pointer would be highly appreciated, especially ho i could make my Raspberry Pi's pulseaudio daemon wait for avahi to settle.

Thanks,
Nix
Comment 22 Frederic Germain 2014-10-24 15:46:32 UTC
I have more information about this bug.
It happens in the SIMD function in ORC, and it's maybe specific to AMD Geode or MMX only (no SSE/SSE2) CPUs
I have it on AMD Geode, when pulseaudio has to apply a volume to the sink.

A quickfix to it could be to launch pulseaudio with PULSE_NO_SIMD env variable ->
PULSE_NO_SIMD=1 pulseaudio --start
But then you loose the optimization you could have with MMX

I'm not sure I have time to fix the bug in ORC, but maybe there is a jedi out there who can find the problem quickly :)

Step to reproduce on Geode platform (Debian Wheezy x86). Alsa card driver is cs5535audio.

> gdb pulseaudio

> pacmd set-sink-volume 0 0x100 (volume is really really loud at 100% on my board)

> paplay mymusic.wav

In gdb ->

Program received signal SIGILL, Illegal instruction.
[Switching to Thread 0xb3235b70 (LWP 3239)]
0xae128031 in ?? ()
(gdb) bt
#0  0xae128031 in ?? ()
#1  0x00003d3c in ?? ()

> cat /proc/$(pidof pulseaudio)/maps  |grep orc
ae118000-ae128000 rw-s 00000000 08:01 56769      /tmp/orcexec.Wk0lzw (deleted)
ae128000-ae138000 r-xs 00000000 08:01 56769      /tmp/orcexec.Wk0lzw (deleted)

It seems gdb cannot rewind stack of orc functions on this architecture, that's pretty sad.

(gdb) disas /r 0xae128000,0xae138000
Dump of assembler code from 0xae128000 to 0xae138000:
   0xae128000:  55      push   %ebp
   0xae128001:  8b 6c 24 08     mov    0x8(%esp),%ebp
   0xae128005:  0f 6e 85 74 01 00 00    movd   0x174(%ebp),%mm0
   0xae12800c:  0f c4 85 94 01 00 00 02 pinsrw $0x2,0x194(%ebp),%mm0
   0xae128014:  0f c4 85 96 01 00 00 03 pinsrw $0x3,0x196(%ebp),%mm0
   0xae12801c:  0f ef c9        pxor   %mm1,%mm1
   0xae12801f:  8b 4d 04        mov    0x4(%ebp),%ecx
   0xae128022:  89 4d 0c        mov    %ecx,0xc(%ebp)
   0xae128025:  8b 45 14        mov    0x14(%ebp),%eax
   0xae128028:  83 7d 0c 00     cmpl   $0x0,0xc(%ebp)
   0xae12802c:  74 54   je     0xae128082
   0xae12802e:  8b 55 0c        mov    0xc(%ebp),%edx
=> 0xae128031:  66 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00    data32 data32 data32 data32 data32 nopw %cs:0x0(%eax,%eax,1)
   0xae128040:  0f 6e 10        movd   (%eax),%mm2
   0xae128043:  0f ef db        pxor   %mm3,%mm3
   0xae128046:  0f 61 d3        punpcklwd %mm3,%mm2
   0xae128049:  0f 6f d9        movq   %mm1,%mm3
   0xae12804c:  0f 65 da        pcmpgtw %mm2,%mm3
   0xae12804f:  0f db d8        pand   %mm0,%mm3
   0xae128052:  0f e4 d0        pmulhuw %mm0,%mm2
   0xae128055:  0f fa d3        psubd  %mm3,%mm2
   0xae128058:  0f 6f d8        movq   %mm0,%mm3
   0xae12805b:  0f 72 e3 10     psrad  $0x10,%mm3
   0xae12805f:  0f 6b db        packssdw %mm3,%mm3
   0xae128062:  0f 6e 20        movd   (%eax),%mm4
   0xae128065:  0f 6f ec        movq   %mm4,%mm5
   0xae128068:  0f e5 eb        pmulhw %mm3,%mm5
   0xae12806b:  0f d5 e3        pmullw %mm3,%mm4
   0xae12806e:  0f 61 e5        punpcklwd %mm5,%mm4
   0xae128071:  0f fe d4        paddd  %mm4,%mm2
   0xae128074:  0f 6b d2        packssdw %mm2,%mm2
---Type <return> to continue, or q <return> to quit---q
Quit

cat /proc/cpuinfo
processor       : 0
vendor_id       : AuthenticAMD
cpu family      : 5
model           : 10
model name      : Geode(TM) Integrated Processor by AMD PCS
stepping        : 2
microcode       : 0x8b
cpu MHz         : 498.053
cache size      : 128 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 1
wp              : yes
flags           : fpu de pse tsc msr cx8 sep pge cmov clflush mmx mmxext 3dnowext 3dnow
bogomips        : 996.10
clflush size    : 32
cache_alignment : 32
address sizes   : 32 bits physical, 32 bits virtual
power management:
Comment 23 Raymond 2014-10-25 11:41:10 UTC
(In reply to Martin-Éric Racine from comment #4)
> I: [alsa-source] alsa-source.c: Overrun!
> I: [alsa-source] alsa-source.c: Increasing minimal latency to 1,00 ms
> D: [alsa-source] alsa-source.c: latency set to 24,99ms
> D: [alsa-source] alsa-source.c: hwbuf_unused=61132
> D: [alsa-source] alsa-source.c: setting avail_min=443
> 


you need to enable DEBUG_TIMING

If pulseaudio did not wakeup in time to read the data from the sound card, this mean hwptr was ahead of appl_ptr by more than one buffer size, 

some of the recorded data were overwrited by the recent record audio, but you still had one buffer size of unreaded data in the buffer 

to recover you still need to use snd_pcm_forward to move appl_ptr to the position which is one buffer size behind hwptr  before you read the remain data from the buffer


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct.