server segfaults in raspian buster

[slowphil]

I have built the code following instructions on a raspi 4 with raspbian buster. I can lauch the server or the client; they run fine independently.

snapcast-server -b 25000 -s "pipe:///tmp/snapfifo?buffer_ms=120&codec=opus&name=default&sampleformat=48000:16:2&timeout_ms=1000" -p 1704 -d Initializing socket: 1705 watching fd 3 using epoll watching fd 4 using epoll watching fd 5 using epoll starting loop

However, as soon as the client (running on the same machine for the moment) reaches the server, the server crashes with a segfault with the following message:

handling event on fd 4. HANDLING INTERCOM PACKET on fd 4 using buffersize of 1500 - read from ::1(48626), 19 Bytes of data: Packet: [ 01005D35 A11B9965 010BB421 5D350000 000064] handling client operation for client ::1 port 48626 offset: 8 0xbee077b0 0xbee077b8 clientmgr: creating client: 3022085429 ADDING client 3022085429 hostname of peer: localhost It is now: 495144.418433783, scheduling next task for 495149.418432098 added client -1272881867(localhost) to stream default resuming reading from pipe watching fd 7 using epoll clientmgr: refreshing client: 3022085429 Client localhost(3022085429) has IP ::1, port 48626 It is now: 495144.418542596, scheduling next task for 495149.418541411 handled event on fd 4 - Event 1 out of 1 handling event on fd 7. read 23040 Bytes from inputpipe We are horribly late when reading from the pipes - Using current timestamp to play back current chunk. Consider adjusting timeout_ms for this stream. sub: t1: 1575116260.839410000, t2: 1575116260.939410000 ret: 0.100000000 sign: -1 read 23040 Bytes of data from /tmp/snapfifo, last read was 23040, reader state: playing, to be played at 1575116260.939410000, current time 1575116260.839410000, diff: -0.100000000 encode opus: chunk: chunksize: 23040 48000 2 5760 encode happened, adjusting chunk size: 14 sending 14 Bytes of audio data Segmentation fault

This happens whenever mopidy is already running or has been running (i.e. some data is already in the fifo) when the server is started.

If I start the server before mopidy, then it is not crashing. But for the moment I cannot get any sound out even though the client seems to receive data. I guess I do not correctly specify which alsa output to use... I can't figure how to use the output of snapcast-client -l to correctly fill in the -c, -m and -s options

[christf]

Thank you for your report. Could you please re-try with the mixer branch? from #40 ?

[christf]

snapcast-client -l is just a different layout for whatever aplay -L should give you. I agree the usability for finding the correct audio output and mixer settings could be enhanced. On my raspberrypi I am using special audio hardware so my setting won't apply. The defaults should work though.

[slowphil]

Yes I tried the mixer branch as it seemed the latest. Today I cannot even reproduce having the server streaming music to the client; it crashes as soon as I start playing music...

snapcast-server -b 25000 -s "pipe:///tmp/snapfifo?buffer_ms=120&codec=opus&name=default&sampleformat=48000:16:2&timeout_ms=1000" -p 1704 -v Initializing socket: 1705 starting loop clientmgr: creating client: 3565651974 ADDING client 3565651974 hostname of peer: localhost added client -729315322(localhost) to stream default clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 We are horribly late when reading from the pipes - Using current timestamp to play back current chunk. Consider adjusting timeout_ms for this stream. read 23040 Bytes of data from /tmp/snapfifo, last read was 424, reader state: playing, to be played at 1575534148.900024000, current time 1575534148.800024000, diff: -0.100000000 Erreur de segmentation

Let me know if that's enough to find what can go wrong or if you need I run the debugger.

Regarding the client alsa sink, I too use an external usb audio system that normally works fine. for instance with snapcast (not 'c') I just pass -s 20 to the client and it works... BTW the documentation for the client options are inconsistent between the README.md and the built-in help, at least regarding the -s option.

[christf]

Hi,

Interesting. Unfortunately this does not narrow down the problem much. How are you ceating the snapfifo and music input? I just added two more commands to illustrate the pipe use: mkfifo /tmp/snapfifo sox input.ogg -r 48000 -t raw -b 16 -e signed -c 2 /tmp/snapfifo Then starting the server: ./src/snapcast-server -s "pipe:///tmp/snapfifo?name=default&codec=opus&sampleformat=48000:16:2&buffer_ms=120" -b 30000 -p 1704 -v

And client: ./src/snapcast-client -H localhost

What do you mean is inconsistent?

On Thu, Dec 05, 2019 at 12:36:24AM -0800, slowphil wrote:

Yes I tried the mixer branch as it seemed the latest. Today I cannot even reproduce having the server streaming music to the client; it crashes as soon as I start playing music...

snapcast-server -b 25000 -s "pipe:///tmp/snapfifo?buffer_ms=120&codec=opus&name=default&sampleformat=48000:16:2&timeout_ms=1000" -p 1704 -v Initializing socket: 1705 starting loop clientmgr: creating client: 3565651974 ADDING client 3565651974 hostname of peer: localhost added client -729315322(localhost) to stream default clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 clientmgr: refreshing client: 3565651974 Client localhost(3565651974) has IP ::1, port 60417 We are horribly late when reading from the pipes - Using current timestamp to play back current chunk. Consider adjusting timeout_ms for this stream. read 23040 Bytes of data from /tmp/snapfifo, last read was 424, reader state: playing, to be played at 1575534148.900024000, current time 1575534148.800024000, diff: -0.100000000 Erreur de segmentation

Let me know if that's enough to find what can go wrong or if you need I run the debugger.

Regarding the client alsa sink, I too use an external usb audio system that normally works fine. for instance with snapcast (not 'c') I just pass -s 20 to the client and it works... BTW the documentation for the client options are inconsistent between the README.md and the built-in help, at least regarding the -s option. -- () ascii ribbon campaign - against html e-mail /\ www.asciiribbon.org - against proprietary attachments

[slowphil]

I did exactly what you indicate and the server still segfaults as soon as the client connects:

rm /tmp/snapfifo mkfifo /tmp/snapfifo sox file_example_OOG_5MG.ogg -r 48000 -t raw -b 16 -e signed -c 2 /tmp/snapfifo & snapcastc/build/src//snapcast-server -s "pipe:///tmp/snapfifo?name=default&codec=opus&sampleformat=48000:16:2&buffer_ms=120" -b 30000 -p 1704 -v Initializing socket: 1705 starting loop clientmgr: creating client: 3836630957 ADDING client 3836630957 hostname of peer: localhost added client -458336339(localhost) to stream default clientmgr: refreshing client: 3836630957 Client localhost(3836630957) has IP ::1, port 37194 We are horribly late when reading from the pipes - Using current timestamp to play back current chunk. Consider adjusting timeout_ms for this stream. read 23040 Bytes of data from /tmp/snapfifo, last read was 23040, reader state: playing, to be played at 1575619458.794049000, current time 1575619458.694049000, diff: -0.100000000 Erreur de segmentation

I'll try to build with debugging symbols during the week-end.

Regarding the documentation, the README.md says

-s index or name of the soundcard

and the output of snapcast-client -h

...[-s \<volume control>] ...

which are contradicting.

[slowphil]

gbd says:

Program received signal SIGSEGV, Segmentation fault. 0x00014918 in intercom_send_audio (ctx=0xee6123, s=0xd05a6421) at /home/pi/snapcastc/src/intercom_srv.c:134 134 VECTOR_ADD(s->packet_buffer, ap); (gdb) bt # 0 0x00014918 in intercom_send_audio (ctx=0xee6123, s=0xd05a6421) at /home/pi/snapcastc/src/intercom_srv.c:134 # 1 0x00013838 in loop () at /home/pi/snapcastc/src/server.c:121 # 2 0x00013fd4 in main (argc=8, argv=0xbefff2d4) at /home/pi/snapcastc/src/server.c:252

is that enough?

[christf]

interesting. I cannot reproduce this (on x86) in the master nor the mixer branch. Can you please confirm this is the mixer branch? If it happens in the same spot, let gdb after the crash letz gdb output s->packet_buffer and ap.

I have pushed some more code into the mixer branch today, it is likely worth checking out again.

[christf]

Does this still happen with the fixes to the vector initialization?

[slowphil]

For sure, I had tested the mixer branch. For not being able to use snapcastc at all in my system, I went back to snapcast. The latest version can now handle TCP sockets for the audio stream and it turns out that resolved the stuttering issues I had previously and which had me searching for alternatives. I have not tested your latest changes to snapcastc partly because I did not understand what you were asking me to do with gdb, partly for lack of motivation and time.

[christf]

well, stability fixes have been applied and this needs a re-test. Since I wasn't able to reproduce this issue and you are using different software now, would you be fine with closing this? In case there is no response, I'll close this end of march.

[slowphil]

Yes, we can close this for the time being.