Ticket #363 (closed defect: fixed)

Opened 4 months ago

Last modified 3 months ago

pulseaudio exits when a remote peer closes a connection to module-simple-protocol-tcp.

Reported by: trustin Assigned to: lennart
Priority: normal Milestone: 0.9.13
Component: daemon Severity: major
Keywords: Cc:

Description

I'm streaming audio from Windows to Linux PulseAudio server using Netcat. The pulseaudio process exits without log messages whenever I kill the nc.exe process. The following is the full command line on the server side:

pulseaudio -vvvvv --daemonize --high-priority --realtime --disallow-module-loading 
           --resample-method=src-sinc-best-quality --no-cpu-limit -n
           -L "module-native-protocol-unix auth-anonymous=1"
           -L "module-native-protocol-tcp auth-ip-acl=192.168.0.0/16;127.0.0.0/8"
           -L "module-simple-protocol-tcp port=4712 rate=44100 format=s16le channels=2"
           -L "module-rescue-streams"
           -L "module-alsa-sink device=hw:1"

And here's the server startup log:

Sep 19 10:18:39 hermes pulseaudio[21270]: main.c: Page size is 4096 bytes
Sep 19 10:18:39 hermes pulseaudio[21270]: main.c: Fresh high-resolution timers available! Bon appetit!
Sep 19 10:18:39 hermes pulseaudio[21270]: protocol-native.c: loading cookie from disk.
Sep 19 10:18:39 hermes pulseaudio[21270]: module.c: Loaded "module-native-protocol-unix" (index: #0; argument: "auth-anonymous=1").
Sep 19 10:18:39 hermes pulseaudio[21270]: protocol-native.c: using already loaded auth cookie.
Sep 19 10:18:39 hermes pulseaudio[21270]: protocol-native.c: using already loaded auth cookie.
Sep 19 10:18:39 hermes pulseaudio[21270]: module.c: Loaded "module-native-protocol-tcp" (index: #1; argument: "auth-ip-acl=192.168.0.0/16;127.0.0.0/8").
Sep 19 10:18:39 hermes pulseaudio[21270]: module.c: Loaded "module-simple-protocol-tcp" (index: #2; argument: "port=4712 rate=44100 format=s16le channels=2").
Sep 19 10:18:39 hermes pulseaudio[21270]: module.c: Loaded "module-rescue-streams" (index: #3; argument: "").
Sep 19 10:18:39 hermes ALSA sound/usb/usbaudio.c:1353: setting usb interface 1:1
Sep 19 10:18:39 hermes pulseaudio[21270]: module-alsa-sink.c: Successfully opened device hw:0.
Sep 19 10:18:39 hermes pulseaudio[21270]: module-alsa-sink.c: Successfully enabled mmap() mode.
Sep 19 10:18:39 hermes pulseaudio[21270]: alsa-util.c: Successfully attached to mixer 'hw:0'
Sep 19 10:18:39 hermes pulseaudio[21270]: alsa-util.c: Cannot find mixer control "Master".
Sep 19 10:18:39 hermes pulseaudio[21270]: alsa-util.c: Using mixer control "PCM".
Sep 19 10:18:39 hermes pulseaudio[21270]: sink.c: Created sink 0 "alsa_output.hw_0" with sample spec "s16le 2ch 44100Hz"
Sep 19 10:18:39 hermes pulseaudio[21270]: source.c: Created source 0 "alsa_output.hw_0.monitor" with sample spec "s16le 2ch 44100Hz"
Sep 19 10:18:39 hermes pulseaudio[21270]: module-alsa-sink.c: Using 4 fragments of size 4408 bytes.
Sep 19 10:18:39 hermes pulseaudio[21270]: alsa-util.c: All 2 channels can be mapped to mixer channels. Using hardware volume control.
Sep 19 10:18:39 hermes pulseaudio[21270]: module-alsa-sink.c: Thread starting up
Sep 19 10:18:39 hermes pulseaudio[21270]: core-util.c: Successfully enabled SCHED_FIFO scheduling for thread, with priority 5.
Sep 19 10:18:39 hermes pulseaudio[21270]: rtpoll.c: Acquired POSIX realtime signal SIGRTMIN+29
Sep 19 10:18:39 hermes pulseaudio[21270]: module-alsa-sink.c: Starting playback.
Sep 19 10:18:39 hermes pulseaudio[21270]: module.c: Loaded "module-alsa-sink" (index: #4; argument: "device=hw:0").
Sep 19 10:18:39 hermes pulseaudio[21270]: main.c: Daemon startup complete.

And then a new connection from nc.exe is accepted and then nc.exe is killed:

Sep 19 10:22:28 hermes pulseaudio[21270]: socket-server.c: TCP connection accepted by tcpwrap.
Sep 19 10:22:28 hermes pulseaudio[21270]: client.c: Created 0 "TCP/IP client from 192.168.0.11:50248"
Sep 19 10:22:28 hermes pulseaudio[21270]: sink-input.c: Created input 0 "TCP/IP client from 192.168.0.11:50248" on alsa_output.hw_0 with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
Sep 19 10:22:28 hermes pulseaudio[21270]: memblockq.c: memblockq requested: maxlength=88200, tlength=0, base=4, prebuf=18446744073709551615, minreq=8820
Sep 19 10:22:28 hermes pulseaudio[21270]: memblockq.c: memblockq sanitized: maxlength=88200, tlength=88200, base=4, prebuf=44100, minreq=8820
Sep 19 10:22:52 hermes pulseaudio[21270]: protocol-simple.c: read(): Connection reset by peer
Sep 19 10:22:52 hermes pulseaudio[21270]: sink-input.c: Freeing output 0 "TCP/IP client from 192.168.0.11:50248"
Sep 19 10:22:52 hermes pulseaudio[21270]: client.c: Freed 0 "TCP/IP client from 192.168.0.11:50248"

Everything looks just OK, but pulseaudio process exits without any further log message.

One the client side (i.e. Windows), I run the following command:

linco -B 16 -C 2 -R 44100 | nc 192.168.0.13 4712

linco.exe is at http://sourceforge.net/project/showfiles.php?group_id=99332&package_id=107331 nc.exe is at http://joncraton.org/files/nc111nt.zip

I am using PulseAudio 0.9.9 on Gentoo Linux.

Change History

09/19/08 11:55:36 changed by coling

You should probably use PulseAudio 0.9.10 at least (it is a major bugfix update from 0.9.9. The current "stable" version is 0.9.12 (for various values of "stable") but 0.9.11 and 0.9.12 are still a little bit experimental (a new glitch free core in 0.9.11 is still causing some fallout).

That said, I notice that you specify --daemonize on the command line. This means pulse should go into the background... Are you sure it's not still running in the background? Try without --daemonize and see what happens.

Make sure your stderr is not redirected and make sure you have compiled pulseaudio with asserts enabled to get useful output.

HTHs

09/21/08 03:21:36 changed by trustin

I've just upgraded to PulseAudio 0.9.10 and the problem still exists. One difference is that it prints out an assertion error right before it exits:

Sep 21 10:22:32 hermes pulseaudio[18690]: object.c: Assertion 'pa_object_refcnt(o) > 0' failed at pulsecore/object.c:60, function pa_object_unref(). Aborting.

I used the --daemonize option on the command line, and it's running in the background. I confirmed the process starts and exits using the 'ps -ef | grep pulse' command.

Thanks!

09/21/08 03:28:31 changed by coling

OK, the assertion is useful. It's showing some memory weirdness, essentially something is being referenced or unreferenced that is not a valid object...

Do you have any patches applied?

Ideally I'd like a full backtrace of the assertion.. You'll need to reproduce this error and then run gdb and get a full backtrace.

Do something like:

ulimit -c unlimited
<reproduce error>
There should be a core.* file (where * will be the pid)
You can then load: gdb `which pulseaudio` core.*
Then type: info threads
For each thread number do:
 thread n
 bt full

Then attach the whole thing here.

09/21/08 04:06:46 changed by trustin

I'm using PulseAudio 0.9.10-r1 distributed with Gentoo Linux. The following is the only patch applied:

Index: pulseaudio-0.9.10/src/daemon/caps.c
===================================================================
--- pulseaudio-0.9.10.orig/src/daemon/caps.c
+++ pulseaudio-0.9.10/src/daemon/caps.c
@@ -131,9 +131,8 @@ int pa_limit_caps(void) {
     return 0;
 }
 
-int pa_drop_caps(void) {
+void pa_drop_caps(void) {
     pa_drop_root();
-    return 0;
 }
 
 #endif

I've tried to generate the binary with debug information, but I couldn't. Here's the GDB output anyway:

GNU gdb 6.7.1
Copyright (C) 2007 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 "x86_64-pc-linux-gnu"...
(no debugging symbols found)
Using host libthread_db library "/lib/libthread_db.so.1".

warning: Can't read pathname for load map: Input/output error.
Reading symbols from /usr/lib64/libpulsecore.so.5...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libpulsecore.so.5
Reading symbols from /usr/lib64/libltdl.so.3...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libltdl.so.3
Reading symbols from /usr/lib64/libsamplerate.so.0...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libsamplerate.so.0
Reading symbols from /usr/lib64/libsndfile.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libsndfile.so.1
Reading symbols from /usr/lib64/libFLAC.so.8...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libFLAC.so.8
Reading symbols from /usr/lib64/libogg.so.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libogg.so.0
Reading symbols from /usr/lib64/liboil-0.3.so.0...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/liboil-0.3.so.0
Reading symbols from /usr/lib64/libdbus-1.so.3...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libdbus-1.so.3
Reading symbols from /lib64/librt.so.1...
(no debugging symbols found)...done.
Loaded symbols for /lib/librt.so.1
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib64/libm.so.6...
(no debugging symbols found)...done.
Loaded symbols for /lib/libm.so.6
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib/libpthread.so.0
Reading symbols from /lib64/libc.so.6...
(no debugging symbols found)...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /usr/lib64/pulse-0.9/modules/module-native-protocol-unix.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/module-native-protocol-unix.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libprotocol-native.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libprotocol-native.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libsocket-server.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libsocket-server.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libsocket-util.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libsocket-util.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libpstream.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libpstream.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libpstream-util.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libpstream-util.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libpdispatch.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libpdispatch.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libtagstruct.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libtagstruct.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libauthkey.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libauthkey.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libauthkey-prop.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libauthkey-prop.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libstrlist.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libstrlist.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libiochannel.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libiochannel.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libipacl.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libipacl.so
Reading symbols from /lib64/libwrap.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib/libwrap.so.0
Reading symbols from /usr/lib64/pulse-0.9/modules/libpacket.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libpacket.so
Reading symbols from /usr/lib64/pulse-0.9/modules/module-native-protocol-tcp.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/module-native-protocol-tcp.so
Reading symbols from /lib64/libnss_files.so.2...
---Type <return> to continue, or q <return> to quit---
(no debugging symbols found)...done.
Loaded symbols for /lib/libnss_files.so.2
Reading symbols from /usr/lib64/pulse-0.9/modules/module-simple-protocol-tcp.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/module-simple-protocol-tcp.so
Reading symbols from /usr/lib64/pulse-0.9/modules/libprotocol-simple.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libprotocol-simple.so
Reading symbols from /usr/lib64/pulse-0.9/modules/module-default-device-restore.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/module-default-device-restore.so
Reading symbols from /usr/lib64/pulse-0.9/modules/module-rescue-streams.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/module-rescue-streams.so
Reading symbols from /usr/lib64/pulse-0.9/modules/module-alsa-sink.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/module-alsa-sink.so
Reading symbols from /usr/lib64/libasound.so.2...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libasound.so.2
Reading symbols from /usr/lib64/pulse-0.9/modules/libalsa-util.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/pulse-0.9/modules/libalsa-util.so

(no debugging symbols found)
Core was generated by `pulseaudio -vvvvv --daemonize --high-priority --realtime --disallow-module-load'.
Program terminated with signal 6, Aborted.
#0  0x00007f38a81950c5 in raise () from /lib/libc.so.6
(gdb) thread 1
[Switching to thread 1 (process 21725)]#0  0x00007f38a81950c5 in raise ()
   from /lib/libc.so.6
(gdb) bt full
#0  0x00007f38a81950c5 in raise () from /lib/libc.so.6
No symbol table info available.
#1  0x00007f38a819697e in abort () from /lib/libc.so.6
No symbol table info available.
#2  0x000000000066888c in pa_object_unref () from /usr/lib/libpulsecore.so.5
No symbol table info available.
#3  0x00007f38a579dc7a in ?? ()
   from /usr/lib64/pulse-0.9/modules/libprotocol-simple.so
No symbol table info available.
#4  0x00000000006688f4 in pa_object_unref () from /usr/lib/libpulsecore.so.5
No symbol table info available.
#5  0x0000000000666d1f in pa_asyncmsgq_done () from /usr/lib/libpulsecore.so.5
No symbol table info available.
#6  0x0000000000667af8 in ?? () from /usr/lib/libpulsecore.so.5
No symbol table info available.
#7  0x0000000000626ad4 in pa_mainloop_dispatch ()
   from /usr/lib/libpulsecore.so.5
No symbol table info available.
#8  0x0000000000626bd4 in pa_mainloop_iterate ()
   from /usr/lib/libpulsecore.so.5
No symbol table info available.
#9  0x0000000000626c17 in pa_mainloop_run () from /usr/lib/libpulsecore.so.5
No symbol table info available.
---Type <return> to continue, or q <return> to quit---
#10 0x0000000000408cca in main ()
No symbol table info available.
(gdb) thread 2
[Switching to thread 2 (process 21726)]#0  0x00007f38a822e0c8 in ppoll ()
   from /lib/libc.so.6
(gdb) bt full
#0  0x00007f38a822e0c8 in ppoll () from /lib/libc.so.6
No symbol table info available.
#1  0x000000000066a2e8 in pa_rtpoll_run () from /usr/lib/libpulsecore.so.5
No symbol table info available.
#2  0x00007f38a5192827 in ?? ()
   from /usr/lib64/pulse-0.9/modules/module-alsa-sink.so
No symbol table info available.
#3  0x000000000066d278 in ?? () from /usr/lib/libpulsecore.so.5
No symbol table info available.
#4  0x00007f38a84c03a7 in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#5  0x00007f38a8236b6d in clone () from /lib/libc.so.6
No symbol table info available.
#6  0x0000000000000000 in ?? ()
No symbol table info available.
(gdb) 

I'd like to run it again with debug symbols attached, but how? What flag do I need to append? I replaced -O3 with -O, removed -fomit-frame-pointers, added -ggdb, and removed -UNDEBUG, but it still doesn't generate debug binary.

09/21/08 12:37:56 changed by coling

Sadly the info is not that useful without the debug symbols :(

Usually -g is your friend for getting debug symbols but I'm not sure how Gentoo works....

09/21/08 12:58:38 changed by trustin

I figured out how to get the meaningful backtrace:

Core was generated by `pulseaudio -vvvvv --daemonize --high-priority --realtime --disallow-module-load'.
Program terminated with signal 6, Aborted.
#0  0x00007fdd9c42d0c5 in raise () from /lib/libc.so.6
(gdb) info threads
  2 process 11108  0x00007fdd9c4c60c8 in ppoll () from /lib/libc.so.6
* 1 process 11107  0x00007fdd9c42d0c5 in raise () from /lib/libc.so.6
(gdb) thread 1
[Switching to thread 1 (process 11107)]#0  0x00007fdd9c42d0c5 in raise ()
   from /lib/libc.so.6
(gdb) bt full
#0  0x00007fdd9c42d0c5 in raise () from /lib/libc.so.6
No symbol table info available.
#1  0x00007fdd9c42e97e in abort () from /lib/libc.so.6
No symbol table info available.
#2  0x00007fdd9df2388c in pa_object_unref (o=<value optimized out>)
    at pulsecore/object.c:60
	__func__ = "pa_object_unref"
	__PRETTY_FUNCTION__ = "pa_object_unref"
#3  0x00007fdd99a35c7a in connection_free (o=<value optimized out>)
    at pulsecore/protocol-simple.c:69
	c = (connection *) 0x877320
	__func__ = "connection_free"
	__PRETTY_FUNCTION__ = "connection_free"
#4  0x00007fdd9df238f4 in pa_object_unref (o=0x6) at pulsecore/object.c:64
	__func__ = "pa_object_unref"
	__PRETTY_FUNCTION__ = "pa_object_unref"
#5  0x00007fdd9df21d1f in pa_asyncmsgq_done (a=0x87e460, 
    ret=<value optimized out>) at ./pulsecore/msgobject.h:52
	__func__ = "pa_asyncmsgq_done"
	__PRETTY_FUNCTION__ = "pa_asyncmsgq_done"
#6  0x00007fdd9df22af8 in asyncmsgq_cb (api=<value optimized out>, 
    e=<value optimized out>, fd=<value optimized out>, 
    events=<value optimized out>, userdata=<value optimized out>)
---Type <return> to continue, or q <return> to quit---
    at pulsecore/thread-mq.c:68
	ret = 11107
	data = (void *) 0x0
	chunk = {memblock = 0x0, index = 0, length = 0}
	object = (pa_msgobject *) 0x877320
	code = 2
	offset = 0
	q = <value optimized out>
	aq = (pa_asyncmsgq *) 0x87e460
	__func__ = "asyncmsgq_cb"
	__PRETTY_FUNCTION__ = "asyncmsgq_cb"
#7  0x00007fdd9dee1ad4 in pa_mainloop_dispatch (m=0x86a6a0)
    at pulse/mainloop.c:679
	dispatched = 0
	__func__ = "pa_mainloop_dispatch"
	__PRETTY_FUNCTION__ = "pa_mainloop_dispatch"
#8  0x00007fdd9dee1bd4 in pa_mainloop_iterate (m=0x86a6a0, 
    block=<value optimized out>, retval=0x7fffa6169ffc) at pulse/mainloop.c:922
	r = 0
	__func__ = "pa_mainloop_iterate"
	__PRETTY_FUNCTION__ = "pa_mainloop_iterate"
#9  0x00007fdd9dee1c17 in pa_mainloop_run (m=0x86a6a0, retval=0x7fffa6169ffc)
    at pulse/mainloop.c:937
---Type <return> to continue, or q <return> to quit---
	r = <value optimized out>
#10 0x0000000000408cca in main (argc=<value optimized out>, 
    argv=<value optimized out>) at daemon/main.c:810
	c = (pa_core *) 0x86b820
	buf = <value optimized out>
	conf = (pa_daemon_conf *) 0x86a000
	mainloop = (pa_mainloop *) 0x86a6a0
	s = 0x86dd50 "\021"
	r = 0
	retval = 0
	d = 21
	daemon_pipe = {-1, 4}
	suid_root = <value optimized out>
	real_root = <value optimized out>
	valid_pid_file = 1
	gid = 4294967295
	allow_realtime = false
	allow_high_priority = <value optimized out>
	ltdl_init = <value optimized out>
	__func__ = "main"
	__PRETTY_FUNCTION__ = "main"
	rl = {value = 9, is_set = true}
(gdb) thread 2
[Switching to thread 2 (process 11108)]#0  0x00007fdd9c4c60c8 in ppoll ()
   from /lib/libc.so.6
(gdb) bt full
#0  0x00007fdd9c4c60c8 in ppoll () from /lib/libc.so.6
No symbol table info available.
#1  0x00007fdd9df252e8 in pa_rtpoll_run (p=0x87e980, wait=true)
    at pulsecore/rtpoll.c:394
	ts = {tv_sec = 1088, tv_nsec = 140589814230882000}
	i = (pa_rtpoll_item *) 0x897310
	r = <value optimized out>
	timeout = {tv_sec = 1088, tv_usec = 140589814230882}
	__func__ = "pa_rtpoll_run"
	__PRETTY_FUNCTION__ = "pa_rtpoll_run"
#2  0x00007fdd9942a827 in thread_func (userdata=<value optimized out>)
    at modules/module-alsa-sink.c:642
	pollfd = <value optimized out>
	revents = 0
	err = <value optimized out>
	n = 1
	ret = <value optimized out>
	u = (struct userdata *) 0x87dee0
	__func__ = "thread_func"
	__PRETTY_FUNCTION__ = "thread_func"
#3  0x00007fdd9df28278 in internal_thread_func (userdata=<value optimized out>)
    at pulsecore/thread-posix.c:73
	t = (pa_thread *) 0x88eef0
---Type <return> to continue, or q <return> to quit---
	__func__ = "internal_thread_func"
	__PRETTY_FUNCTION__ = "internal_thread_func"
#4  0x00007fdd9c7583a7 in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#5  0x00007fdd9c4ceb6d in clone () from /lib/libc.so.6
No symbol table info available.
#6  0x0000000000000000 in ?? ()
No symbol table info available.
(gdb) 

09/21/08 13:09:40 changed by trustin

This one might be better (replaced -O option with -O0):

Core was generated by `pulseaudio -vvvvv --daemonize --high-priority --realtime --disallow-module-load'.
Program terminated with signal 6, Aborted.
#0  0x00007f5af392a0c5 in raise () from /lib/libc.so.6
(gdb) info threads
  2 process 12206  0x00007f5af39c30c8 in ppoll () from /lib/libc.so.6
* 1 process 12205  0x00007f5af392a0c5 in raise () from /lib/libc.so.6
(gdb) thread 1
[Switching to thread 1 (process 12205)]#0  0x00007f5af392a0c5 in raise ()
   from /lib/libc.so.6
(gdb) bt full
#0  0x00007f5af392a0c5 in raise () from /lib/libc.so.6
No symbol table info available.
#1  0x00007f5af392b97e in abort () from /lib/libc.so.6
No symbol table info available.
#2  0x00000000006774fa in pa_object_unref (o=0xb21320) at pulsecore/object.c:60
	__func__ = "pa_object_unref"
	__PRETTY_FUNCTION__ = "pa_object_unref"
#3  0x00007f5af0f2f298 in connection_unref (o=0xb21320)
    at pulsecore/protocol-simple.c:69
No locals.
#4  0x00007f5af0f2f320 in connection_free (o=0xb21320)
    at pulsecore/protocol-simple.c:143
	c = (connection *) 0xb21320
	__func__ = "connection_free"
	__PRETTY_FUNCTION__ = "connection_free"
#5  0x0000000000677580 in pa_object_unref (o=0xb21320) at pulsecore/object.c:64
	__func__ = "pa_object_unref"
	__PRETTY_FUNCTION__ = "pa_object_unref"
#6  0x0000000000674536 in pa_msgobject_unref (o=0xb21320)
    at ./pulsecore/msgobject.h:52
No locals.
#7  0x0000000000675137 in pa_asyncmsgq_done (a=0xb28460, ret=0)
    at pulsecore/asyncmsgq.c:220
---Type <return> to continue, or q <return> to quit---
	__func__ = "pa_asyncmsgq_done"
	__PRETTY_FUNCTION__ = "pa_asyncmsgq_done"
#8  0x0000000000675ec9 in asyncmsgq_cb (api=0xb146f8, e=0xb28930, fd=16, 
    events=PA_IO_EVENT_INPUT, userdata=0xb27f00) at pulsecore/thread-mq.c:68
	ret = 0
	data = (void *) 0x0
	chunk = {memblock = 0x0, index = 0, length = 0}
	object = (pa_msgobject *) 0xb21320
	code = 2
	offset = 0
	q = (pa_thread_mq *) 0xb27f00
	aq = (pa_asyncmsgq *) 0xb28460
	__func__ = "asyncmsgq_cb"
	__PRETTY_FUNCTION__ = "asyncmsgq_cb"
#9  0x00000000006290ed in dispatch_pollfds (m=0xb146a0) at pulse/mainloop.c:679
	e = (pa_io_event *) 0xb28930
	r = 0
	k = 1
	__func__ = "dispatch_pollfds"
	__PRETTY_FUNCTION__ = "dispatch_pollfds"
#10 0x0000000000629d2c in pa_mainloop_dispatch (m=0xb146a0)
    at pulse/mainloop.c:892
	dispatched = 0
---Type <return> to continue, or q <return> to quit---
	__func__ = "pa_mainloop_dispatch"
	__PRETTY_FUNCTION__ = "pa_mainloop_dispatch"
#11 0x0000000000629ea0 in pa_mainloop_iterate (m=0xb146a0, block=1, 
    retval=0x7ffffd3e8264) at pulse/mainloop.c:922
	r = 1
	__func__ = "pa_mainloop_iterate"
	__PRETTY_FUNCTION__ = "pa_mainloop_iterate"
#12 0x0000000000629efc in pa_mainloop_run (m=0xb146a0, retval=0x7ffffd3e8264)
    at pulse/mainloop.c:937
	r = 1
#13 0x000000000040a055 in main (argc=21, argv=0x7ffffd3e83a8)
    at daemon/main.c:810
	c = (pa_core *) 0xb15820
	buf = (pa_strbuf *) 0xb142f0
	conf = (pa_daemon_conf *) 0xb14000
	mainloop = (pa_mainloop *) 0xb146a0
	s = 0xb17d50 "\021"
	r = 0
	retval = 0
	d = 21
	daemon_pipe = {-1, 4}
	suid_root = false
	real_root = true
---Type <return> to continue, or q <return> to quit---
	valid_pid_file = 1
	gid = 4294967295
	allow_realtime = true
	allow_high_priority = true
	ltdl_init = true
	__func__ = "main"
	__PRETTY_FUNCTION__ = "main"
	rl = {value = 9, is_set = true}
(gdb) thread 2
[Switching to thread 2 (process 12206)]#0  0x00007f5af39c30c8 in ppoll ()
   from /lib/libc.so.6
(gdb) bt full
#0  0x00007f5af39c30c8 in ppoll () from /lib/libc.so.6
No symbol table info available.
#1  0x000000000067942d in pa_rtpoll_run (p=0xb28980, wait=true)
    at pulsecore/rtpoll.c:394
	ts = {tv_sec = 4352, tv_nsec = 0}
	i = (pa_rtpoll_item *) 0xb41310
	r = 0
	timeout = {tv_sec = 4352, tv_usec = 0}
	__func__ = "pa_rtpoll_run"
	__PRETTY_FUNCTION__ = "pa_rtpoll_run"
#2  0x00007f5af092345c in thread_func (userdata=0xb27ee0)
    at modules/module-alsa-sink.c:642
	ret = 1
	u = (struct userdata *) 0xb27ee0
	__func__ = "thread_func"
	__PRETTY_FUNCTION__ = "thread_func"
#3  0x000000000067d8e6 in internal_thread_func (userdata=0xb38ef0)
    at pulsecore/thread-posix.c:73
	t = (pa_thread *) 0xb38ef0
	__func__ = "internal_thread_func"
	__PRETTY_FUNCTION__ = "internal_thread_func"
#4  0x00007f5af3c553a7 in start_thread () from /lib/libpthread.so.0
No symbol table info available.
---Type <return> to continue, or q <return> to quit---
#5  0x00007f5af39cbb6d in clone () from /lib/libc.so.6
No symbol table info available.
#6  0x0000000000000000 in ?? ()
No symbol table info available.
(gdb) 

09/21/08 13:33:08 changed by trustin

FYI, you can always reproduce this issue using 'telnet localhost <port>' instead of netcat or linco.

09/21/08 13:42:52 changed by coling

Well I think lennart will need to debug fully, but I suspect it's a corner case that is unveiled due to your specific module load and/or the order you've loaded them in.

Can you reproduce using the default.pa module loading script and subsequent pacmd calls to set things up the way you need with the additional modules?

09/21/08 14:13:55 changed by trustin

OK. Here's the reproduction step as you asked:

Startup:

hermes / # pulseaudio -vvvvv
I: core-util.c: Successfully gained nice level -11.
W: main.c: This program is not intended to be run as root (unless --system is specified).
W: pid.c: Stale PID file, overwriting.
I: main.c: This is PulseAudio 0.9.10
I: main.c: Page size is 4096 bytes
I: main.c: Fresh high-resolution timers available! Bon appetit!
D: cli-command.c: Checking for existance of '/usr/lib64/pulse-0.9/modules/module-hal-detect.so': success
I: module-hal-detect.c: Trying capability alsa
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/computer_alsa_sequencer
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/computer_alsa_timer
D: module-hal-detect.c: Loading module-alsa-sink with arguments 'device_id=1 sink_name=alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0'
D: alsa-util.c: Trying front:1...
I: module-alsa-sink.c: Successfully opened device front:1.
I: module-alsa-sink.c: Successfully enabled mmap() mode.
ALSA lib control.c:909:(snd_ctl_open_noupdate) Invalid CTL front:1
I: alsa-util.c: Unable to attach to mixer front:1: No such file or directory
I: alsa-util.c: Successfully attached to mixer 'hw:1'
I: alsa-util.c: Cannot find mixer control "Master".
I: alsa-util.c: Using mixer control "PCM".
I: sink.c: Created sink 0 "alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0" with sample spec "s16le 2ch 44100Hz"
I: source.c: Created source 0 "alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0.monitor" with sample spec "s16le 2ch 44100Hz"
I: module-alsa-sink.c: Using 4 fragments of size 4408 bytes.
I: alsa-util.c: All 2 channels can be mapped to mixer channels. Using hardware volume control.
D: module-alsa-sink.c: Thread starting up
D: rtpoll.c: Acquired POSIX realtime signal SIGRTMIN+29
I: module-alsa-sink.c: Starting playback.
I: module.c: Loaded "module-alsa-sink" (index: #0; argument: "device_id=1 sink_name=alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0").
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_control__1
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/pci_8086_284b_sound_card_0_alsa_playback_1
D: module-hal-detect.c: Loading module-alsa-sink with arguments 'device_id=0 sink_name=alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0'
D: alsa-util.c: Trying front:0...
I: module-alsa-sink.c: Successfully opened device front:0.
I: module-alsa-sink.c: Successfully enabled mmap() mode.
ALSA lib control.c:909:(snd_ctl_open_noupdate) Invalid CTL front:0
I: alsa-util.c: Unable to attach to mixer front:0: No such file or directory
I: alsa-util.c: Successfully attached to mixer 'hw:0'
I: alsa-util.c: Using mixer control "Master".
I: sink.c: Created sink 1 "alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0" with sample spec "s16le 2ch 44100Hz"
I: source.c: Created source 1 "alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0.monitor" with sample spec "s16le 2ch 44100Hz"
I: module-alsa-sink.c: Using 4 fragments of size 4352 bytes.
I: alsa-util.c: All 2 channels can be mapped to mixer channels. Using hardware volume control.
D: module-alsa-sink.c: Thread starting up
D: rtpoll.c: Acquired POSIX realtime signal SIGRTMIN+28
I: module-alsa-sink.c: Starting playback.
I: module.c: Loaded "module-alsa-sink" (index: #1; argument: "device_id=0 sink_name=alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0").
D: module-hal-detect.c: Loading module-alsa-source with arguments 'device_id=0 source_name=alsa_input.pci_8086_284b_sound_card_0_alsa_capture_0'
D: alsa-util.c: Trying front:0...
I: module-alsa-source.c: Successfully opened device front:0.
I: module-alsa-source.c: Successfully enabled mmap() mode.
ALSA lib control.c:909:(snd_ctl_open_noupdate) Invalid CTL front:0
I: alsa-util.c: Unable to attach to mixer front:0: No such file or directory
I: alsa-util.c: Successfully attached to mixer 'hw:0'
I: alsa-util.c: Using mixer control "Capture".
I: source.c: Created source 2 "alsa_input.pci_8086_284b_sound_card_0_alsa_capture_0" with sample spec "s16le 2ch 44100Hz"
I: module-alsa-source.c: Using 4 fragments of size 4352 bytes.
I: alsa-util.c: All 2 channels can be mapped to mixer channels. Using hardware volume control.
D: module-alsa-source.c: Thread starting up
D: rtpoll.c: Acquired POSIX realtime signal SIGRTMIN+27
I: module.c: Loaded "module-alsa-source" (index: #2; argument: "device_id=0 source_name=alsa_input.pci_8086_284b_sound_card_0_alsa_capture_0").
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/pci_8086_284b_sound_card_0_alsa_hw_specific_0
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/pci_8086_284b_sound_card_0_alsa_control__1
I: module-hal-detect.c: Loaded 3 modules.
I: module.c: Loaded "module-hal-detect" (index: #3; argument: "").
D: cli-command.c: Checking for existance of '/usr/lib64/pulse-0.9/modules/module-esound-protocol-unix.so': success
I: module.c: Loaded "module-esound-protocol-unix" (index: #4; argument: "").
I: protocol-native.c: loading cookie from disk.
I: module.c: Loaded "module-native-protocol-unix" (index: #5; argument: "").
I: module-volume-restore.c: starting with empty ruleset.
I: module.c: Loaded "module-volume-restore" (index: #6; argument: "").
I: module.c: Loaded "module-default-device-restore" (index: #7; argument: "").
I: module.c: Loaded "module-rescue-streams" (index: #8; argument: "").
D: module-suspend-on-idle.c: Sink alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0 becomes idle.
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0 becomes idle.
D: module-suspend-on-idle.c: Source alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0.monitor becomes idle.
D: module-suspend-on-idle.c: Source alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0.monitor becomes idle.
D: module-suspend-on-idle.c: Source alsa_input.pci_8086_284b_sound_card_0_alsa_capture_0 becomes idle.
I: module.c: Loaded "module-suspend-on-idle" (index: #9; argument: "").
D: cli-command.c: Checking for existance of '/usr/lib64/pulse-0.9/modules/module-gconf.so': failure
D: cli-command.c: Checking for existance of '/usr/lib64/pulse-0.9/modules/module-x11-publish.so': success
D: module-x11-publish.c: using already loaded auth cookie.
E: x11wrap.c: XOpenDisplay() failed
E: module.c: Failed to load  module "module-x11-publish" (argument: ""): initialization failed.
E: main.c: Module load failed.
I: main.c: Daemon startup complete.
D: module-hal-detect.c: dbus: interface=org.freedesktop.DBus, path=/org/freedesktop/DBus, member=NameAcquired
I: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0 idle for too long, suspending ...
I: module-alsa-sink.c: Device suspended...
I: module-suspend-on-idle.c: Sink alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0 idle for too long, suspending ...
I: module-alsa-sink.c: Device suspended...
I: module-suspend-on-idle.c: Source alsa_input.pci_8086_284b_sound_card_0_alsa_capture_0 idle for too long, suspending ...
I: module-alsa-source.c: Device suspended...
I: module-suspend-on-idle.c: Source alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0.monitor idle for too long, suspending ...
I: module-suspend-on-idle.c: Source alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0.monitor idle for too long, suspending ...
I: main.c: Got signal SIGUSR2.
I: module.c: Loaded "module-cli-protocol-unix" (index: #10; argument: "").
I: client.c: Created 0 "UNIX socket client"
D: module-hal-detect.c: dbus: interface=org.freedesktop.Hal.Device, path=/org/freedesktop/Hal/devices/computer_power_supply_battery_CMB1, member=PropertyModified

Loaded module-simple-protocol-tcp using pacmd:

hermes ~ # pacmd
Welcome to PulseAudio! Use "help" for usage information.
>>> load-module module-simple-protocol-tcp port=4712 rate=44100 format=s16le channels=2

The log message when module-simple-protocol-tcp is loaded:

I: module.c: Loaded "module-simple-protocol-tcp" (index: #11; argument: "port=4712 rate=44100 format=s16le channels=2").

Now run the telnet client in the same machine:

hermes ~ # telnet localhost 4712
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
^]
telnet> close
Connection closed.

PulseAudio output:

I: socket-server.c: TCP connection accepted by tcpwrap.
I: client.c: Created 1 "TCP/IP client from 127.0.0.1:48273"
I: module-alsa-sink.c: Trying resume...
I: module-alsa-sink.c: Resumed successfully...
I: module-alsa-sink.c: Starting playback.
D: module-suspend-on-idle.c: Sink alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0 becomes idle.
D: module-suspend-on-idle.c: Sink alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0 becomes busy.
I: sink-input.c: Created input 0 "TCP/IP client from 127.0.0.1:48273" on alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
D: memblockq.c: memblockq requested: maxlength=88200, tlength=0, base=4, prebuf=18446744073709551615, minreq=8820
D: memblockq.c: memblockq sanitized: maxlength=88200, tlength=88200, base=4, prebuf=44100, minreq=8820
I: module-volume-restore.c: Creating new entry for <pulsecore/protocol-simple.c$TCP/IP client from 127.0.0.1:48273>
D: protocol-simple.c: read(): EOF
D: module-suspend-on-idle.c: Sink alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0 becomes idle.
D: module-suspend-on-idle.c: Sink alsa_output.usb_device_8bb_2704_noserial_if0_sound_card_0_alsa_playback_0 becomes idle.
I: sink-input.c: Freeing output 0 "TCP/IP client from 127.0.0.1:48273"
I: client.c: Freed 1 "TCP/IP client from 127.0.0.1:48273"
E: object.c: Assertion 'pa_object_refcnt(o) > 0' failed at pulsecore/object.c:60, function pa_object_unref(). Aborting.
Aborted (core dumped)

09/22/08 02:44:21 changed by trustin

10/01/08 03:45:26 changed by lennart

  • milestone set to 0.9.13.

10/02/08 00:05:08 changed by lennart

  • status changed from new to closed.
  • resolution set to fixed.

m-s-p-t should now work fine again in PA git.