search

owntone / owntone-server

Linux/FreeBSD DAAP (iTunes) and MPD audio server with support for AirPlay 1 and 2 speakers (multiroom), Apple Remote (and compatibles), Chromecast, Spotify and internet radio.
https://owntone.github.io/owntone-server
GNU General Public License v2.0
2.05k stars 235 forks source link

forked-daapd seems to hang completely after havin problems connecting to an airplay speaker #773

Closed LordMyschkin closed 5 years ago

LordMyschkin commented 5 years ago

for a few days, I noticed that forked-daapd repreatedly hangs after trying to connect to my Boston MC2000 Airplay speaker - this is also the speaker with the least stable connection (by WLAN as well as by LAN), meaning it disconnects often for a few seconds trying to re-synch. Im am using latest master on Raspbian strech Before having to restart the service, log tells

[2019-07-13 13:49:38] [ LOG] artwork: Bug! No persistentid in call to process_group() [2019-07-13 13:52:45] [ LOG] artwork: Bug! No persistentid in call to process_group() [2019-07-13 13:55:41] [ LOG] artwork: Bug! No persistentid in call to process_group() [2019-07-13 13:57:46] [ LOG] artwork: Bug! No persistentid in call to process_group() [2019-07-13 14:01:18] [ LOG] artwork: Bug! No persistentid in call to process_group() [2019-07-13 14:03:34] [ LOG] artwork: Bug! No persistentid in call to process_group() [2019-07-13 14:06:29] [ LOG] artwork: Bug! No persistentid in call to process_group() [2019-07-13 14:09:41] [ LOG] artwork: Bug! No persistentid in call to process_group() [2019-07-13 16:48:16] [ LOG] raop: Send error for 'MC200Air': Connection refused [2019-07-13 17:00:13] [ LOG] player: Source is not providing sufficient data, temporarily suspending playback (deficit=265248/264600 bytes)

ejurgensen commented 5 years ago

Thanks for reporting. A few questions:

  1. Does the error happen at 16:48 or 17:00? The two errors in the log are very different, one is a connection error to the device, the other is the source (a radio station?) not delivering enough data (=an underrun).
  2. Did the error start appearing after this commit https://github.com/ejurgensen/forked-daapd/commit/3928ab6f8266ef84cc8310cfc4ee6f8ebb0c21e6? I screwed up underrun handling with that commit :-) But I think I fixed it again with the commits yesterday, so I would also like to know if the error appears with a completely fresh build.

BTW could you open an other issue with artwork bug? Please include debug level logging of whatever comes before one of those log messages.

ejurgensen commented 5 years ago

Had a look at it, and there was a bug in my recent commits. It would cause a deadlock on radio stream underrun, which might be what you experienced. It should be fixed now. Hope you can build with the above commit, hopefully it now works.

LordMyschkin commented 5 years ago

I am not sure when the error happened, I just noticed Radio was playing first und was not when I reentered the room. I will try to reproduce the artwork bug - I have no artwork with my files, so I did not mention it...

Today i recompiled, set loglevel to debug and started the webradio that was playing yesterday, no problem with the service dying; just that mc200Air stopped playing maybe related to the log below:

[2019-07-14 15:45:09] [DEBUG] db: Running query 'END TRANSACTION;' [2019-07-14 15:45:12] [DEBUG] raop: keep_alive: Sending OPTIONS to 'MC200Air' [2019-07-14 15:45:12] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Samsung W_Audio E750_d1:e1:b5' [2019-07-14 15:45:20] [DEBUG] mpd: MPD message: status [2019-07-14 15:45:20] [DEBUG] player: Player status: playing [2019-07-14 15:45:20] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';' [2019-07-14 15:45:20] [DEBUG] db: Running query 'SELECT COUNT() FROM queue;' [2019-07-14 15:45:20] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2019-07-14 15:45:20] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 4277 ORDER BY pos;' [2019-07-14 15:45:20] [DEBUG] db: Running query 'END TRANSACTION;' [2019-07-14 15:45:20] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (4277) [2019-07-14 15:45:20] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2019-07-14 15:45:20] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (4277) [2019-07-14 15:45:20] [DEBUG] db: Running query 'SELECT pos FROM queue WHERE id = 4277;' [2019-07-14 15:45:20] [DEBUG] db: Fetch by pos: item (4277) has absolute pos 1 [2019-07-14 15:45:20] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE pos = 2 ORDER BY pos;' [2019-07-14 15:45:20] [DEBUG] db: Fetch by pos: fetched item (id=4281, pos=2, file-id=2893) [2019-07-14 15:45:20] [DEBUG] db: Running query 'END TRANSACTION;' [2019-07-14 15:45:20] [DEBUG] db: Fetch by pos: fetched item (id=4281, pos=2, file-id=2893) [2019-07-14 15:45:20] [DEBUG] mpd: MPD message: currentsong [2019-07-14 15:45:20] [DEBUG] player: Player status: playing [2019-07-14 15:45:20] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2019-07-14 15:45:20] [DEBUG] db: Starting enum 'SELECT FROM queue f WHERE id = 4277 ORDER BY pos;' [2019-07-14 15:45:20] [DEBUG] db: Running query 'END TRANSACTION;' [2019-07-14 15:45:23] [ LOG] raop: Device 'MC200Air' closed RTSP connection [2019-07-14 15:45:23] [DEBUG] raop: Cleaning up failed session (deferred) on device 'MC200Air' [2019-07-14 15:45:23] [DEBUG] player: Callback request received, id is 1 [2019-07-14 15:45:23] [DEBUG] player: Making deferred callback to device_streaming_cb, id was 1 [2019-07-14 15:45:23] [DEBUG] player: Callback from AirPlay to device_streaming_cb (status -1) [2019-07-14 15:45:23] [ LOG] player: The AirPlay device 'MC200Air' FAILED

A minute after writing that lines, both activated speakers FAILED following this lines is this a second bug (for another issue) or the same one?

[2019-07-14 16:58:38] [ WARN] player: Output delay detected: player is 31 ticks behind, cat ching up [2019-07-14 16:58:39] [DEBUG] player: Player status: playing [2019-07-14 16:58:39] [ WARN] player: Output delay detected: player is 33 ticks behind, cat ching up [2019-07-14 16:58:39] [DEBUG] db: Running query 'BEGIN TRANSACTION;' [2019-07-14 16:58:39] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE id = 4277 ORDER BY pos;' [2019-07-14 16:58:39] [DEBUG] db: Running query 'END TRANSACTION;' [2019-07-14 16:58:39] [ WARN] player: Output delay detected: player is 31 ticks behind, cat ching up [2019-07-14 16:58:39] [ WARN] player: Output delay detected: player is 28 ticks behind, cat ching up [2019-07-14 16:58:40] [ WARN] player: Output delay detected: player is 29 ticks behind, cat ching up [2019-07-14 16:58:40] [ WARN] player: Output delay detected: player is 25 ticks behind, cat ching up [2019-07-14 16:58:40] [ WARN] player: Output delay detected: player is 28 ticks behind, cat ching up [2019-07-14 16:58:40] [ WARN] player: Output delay detected: player is 22 ticks behind, cat ching up [2019-07-14 16:58:41] [ WARN] player: Output delay detected: player is 25 ticks behind, cat ching up [2019-07-14 16:58:41] [ WARN] player: Output delay detected: player is 25 ticks behind, cat ching up [2019-07-14 16:58:42] [ WARN] player: Output delay detected: player is 30 ticks behind, cat ching up [2019-07-14 16:58:42] [ WARN] player: Output delay detected: player is 25 ticks behind, cat ching up [2019-07-14 16:58:43] [ WARN] player: Output delay detected: player is 24 ticks behind, cat ching up [2019-07-14 16:58:45] [DEBUG] raop: keep_alive: Sending OPTIONS to 'MC200Air' [2019-07-14 16:58:45] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Samsung WAudio E750 d1:e1:b5' [2019-07-14 16:58:47] [ WARN] player: Output delay detected: player is 43 ticks behind, cat ching up [2019-07-14 16:58:47] [ WARN] player: Output delay detected: player is 43 ticks behind, cat ching up [2019-07-14 16:58:48] [ WARN] player: Output delay detected: player is 52 ticks behind, cat ching up [2019-07-14 16:58:49] [DEBUG] mpd: MPD message: status [2019-07-14 16:58:49] [ WARN] player: Output delay detected: player is 124 ticks behind, ca tching up [2019-07-14 16:58:51] [DEBUG] player: Player status: playing [2019-07-14 16:58:51] [ LOG] player: Output delay detected (behind=229, max=150), resettin g all outputs [2019-07-14 16:58:51] [DEBUG] player: Removing callback to device_streaming_cb, id 1 [2019-07-14 16:58:51] [DEBUG] player: Registered callback to device_flush_cb with id 1 (dev ice 0x20805e0, MC200Air) [2019-07-14 16:58:51] [DEBUG] player: Number of active callbacks: 2 [2019-07-14 16:58:51] [DEBUG] raop: flush: Sending FLUSH to 'MC200Air' [2019-07-14 16:58:51] [DEBUG] player: Removing callback to device_streaming_cb, id 0 [2019-07-14 16:58:51] [DEBUG] player: Registered callback to device_flush_cb with id 0 (dev ice 0x2176530, Samsung W_Audio E750_d1:e1:b5) [2019-07-14 16:58:51] [DEBUG] player: Number of active callbacks: 2 [2019-07-14 16:58:51] [DEBUG] raop: flush: Sending FLUSH to 'Samsung W_Audio E750_d1:e1:b 5' [2019-07-14 16:58:51] [DEBUG] mpd: Asynchronous listener callback called with event type 1.

ejurgensen commented 5 years ago

Well it seems the deadlock caused by underrun is solved, so I'm inclined to close this issue and track the Airplay device errors via #775.