search

badaix / snapcast

Synchronous multiroom audio player
GNU General Public License v3.0
6.21k stars 456 forks source link

Snapserver hangs after adding streams via RPC involving external processes #1070

Open skyslasher opened 2 years ago

skyslasher commented 2 years ago

Describe the bug Snapserver hangs after using the JSON RPC Control API to add a stream that spawns an external process (e.g. shairport-sync). Creating an alsa stream works in the same environment.

Steps to Reproduce

  1. Start a vanilla snapserver instance. Process looks like 
    mrmaster@multiroom-master:~$ ps axf
[...]
83754 ?        S<sl   0:00 /usr/bin/snapserver --logging.sink=system --server.datadir=/var/lib/snapserver
mrmaster@multiroom-master:~$
  2. Connect to the JSON RPC Control API and add an airplay stream. The API does not come back, Snapserver hangs, nc has to be terminated with CTRL-C 
    mrmaster@multiroom-master:~$ nc localhost 1705
{"jsonrpc":"2.0","method":"Stream.AddStream","params":{"streamUri":"airplay:\/\/\/\/shairport-sync?chunk_ms=20&codec=pcm&devicename=Airplay&name=Airplay&port=5000&sampleformat=44100:16:2"},"id":13}
^C
mrmaster@multiroom-master:~$
  3. Process list looks like 
    mrmaster@multiroom-master:~$ ps axf
[...]
83754 ?        S<sl   0:00 /usr/bin/snapserver --logging.sink=system --server.datadir=/var/lib/snapserver
83780 ?        S<l    0:01  \_ /usr/bin/shairport-sync --name=Airplay --output=stdout --use-stderr --get-coverart --metadata-pipename=/tmp/shairmeta.83754.5000 --port=5000
mrmaster@multiroom-master:~$
  4. Using systemctl to stop snapserver does not come back, has to be terminated with CTRL-C. Process list looks like 
    mrmaster@multiroom-master:~$ sudo systemctl stop snapserver
^C
mrmaster@multiroom-master:~$ ps axf
[...]
83754 ?        S<sl   0:00 /usr/bin/snapserver --logging.sink=system --server.datadir=/var/lib/snapserver
83780 ?        Z<     0:01  \_ [shairport-sync] <defunct>
mrmaster@multiroom-master:~$
  5. Need to kill -9 snapserver. When running from the commandline with snapserver --logging.filter debug, snapserver cannot be terminated with CTRL-C on the console.

Environment details

Logfile Generated with snapserver --logging.filter debug:

[...]
2022-11-03 19-18-03.209 [Debug] (StreamSessionWS) getNextMessage: Time, size: 34, id: 58793, refers: 0
2022-11-03 19-18-03.209 [Debug] (Server) onMessageReceived: Time, size: 34, id: 58793, refers: 0, sent: 22,801219, recv: 542599,981412
2022-11-03 19-18-03.228 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 3746, refers: 0
2022-11-03 19-18-03.228 [Debug] (Server) onMessageReceived: Time, size: 8, id: 3746, refers: 0, sent: 542612,202648, recv: 542600,510
2022-11-03 19-18-03.802 [Info] (Server) Stream.AddStream("airplay:////shairport-sync?chunk_ms=20&codec=pcm&devicename=Airplay&name=Airplay&port=5000&sampleformat=44100:16:2")
2022-11-03 19-18-03.802 [Debug] (parse) StreamUri: airplay:////shairport-sync?chunk_ms=20&codec=pcm&devicename=Airplay&name=Airplay&port=5000&sampleformat=44100:16:2
2022-11-03 19-18-03.802 [Debug] (parse) StreamUri.toString: airplay://///shairport-sync?chunk_ms=20&codec=pcm&devicename=Airplay&name=Airplay&port=5000&sampleformat=44100:16:2
2022-11-03 19-18-03.802 [Info] (PcmStream) PcmStream: Airplay, sampleFormat: 44100:16:2
2022-11-03 19-18-03.802 [Debug] (AsioStream) Chunk duration: 20 ms, frames: 882, size: 3528
2022-11-03 19-18-03.802 [Debug] (ProcessStream) Watchdog timeout: 0
2022-11-03 19-18-03.802 [Info] (AirplayStream) Metadata support not enabled (HAS_EXPAT not defined)
2022-11-03 19-18-03.802 [Debug] (PcmStream) Start: Airplay, type: airplay, sampleformat: 44100:16:2, codec: pcm
2022-11-03 19-18-03.802 [Info] (PcmEnc) Init
2022-11-03 19-18-03.805 [Debug] (ProcessStream) Launching: '/usr/bin/shairport-sync', with params: '"--name=Airplay" --output=stdout --use-stderr --get-coverart "--metadata-pipename=/tmp/shairmeta.83976.5000" --port=5000', in path: '/usr/bin/'
2022-11-03 19-18-03.917 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 5118, refers: 0
2022-11-03 19-18-03.918 [Debug] (Server) onMessageReceived: Time, size: 8, id: 5118, refers: 0, sent: 542572,428889, recv: 542600,690078
2022-11-03 19-18-03.946 [Debug] (StreamSessionWS) on_read_ws, ec: system:0, bytes_transferred: 34
2022-11-03 19-18-03.946 [Debug] (StreamSessionWS) getNextMessage: Time, size: 34, id: 651, refers: 0
2022-11-03 19-18-03.946 [Debug] (Server) onMessageReceived: Time, size: 34, id: 651, refers: 0, sent: 0,0, recv: 542600,718638

Log stops here, process hangs.

ian-robertson commented 9 months ago

This issue appears to be difficult to repeat reliably (at least on my system (Ubuntu 22.04, snapserver v0.27 snapclient v0.27) Initially I tried the following which worked. Add a stream: {"id":8,"jsonrpc":"2.0","method":"Stream.AddStream","params":{"streamUri":"pipe:///tmp/snapfifo?name=stream 2"}} Working - steam added correctly {"id":8,"jsonrpc":"2.0","result":{"id":"stream 2"}} Response OK

-and remove a stream: {"id":8,"jsonrpc":"2.0","method":"Stream.RemoveStream","params":{"id":"stream 2"}} also works {"id":8,"jsonrpc":"2.0","result":{"id":"stream 2"}} Response OK

However, subsequent attempts to add similar streams, e.g.: {"id":10,"jsonrpc":"2.0","method":"Stream.AddStream","params":{"streamUri":"pipe:///tmp/snapfifo?name=pulse&mode=read&sampleformat=48000:16:2&PULSE_LATENCY_MSEC=60"}}

fail in the way described by skyslasher. The snapserver hangs and must be killed with pkill -9.

I have have tried different length URIs in case there is evidence of a buffer size limit. The results are variable. I have also tried deleting and recreating a fresh fifo file as the stream input. This has no effect. Similarly, I have added the parameter "mode=read" to the AddStream call. Again without effect. I'll try the "nightly build" version of snapserver to see if the problem still exists.