Closed tomgadow closed 4 years ago
ejurgensen
commented
4 years ago Thanks for a thorough error report. I tried updating my shairport-sync to see if I could reproduce, but unfortunately couldn't. I also didn't see shairport-sync make those dacp requests. Do you have any pointers on steps to reproduce?
In any case you are right that forked-daapd should have some sort of protection againt log file spamming. I will look into that.
tomgadow
commented
4 years ago /tmp/fo-da/sbin/forked-daapd -f[ LOG] lib: Library init scan completed in 4 sec (0 changes)lsof -p $(pidof forked-daapd) |wc -l
256 # sometimes there are 255systemctl start shairport-sync.service# find output name and number
mpc outputs
mpc enable 38252mpc -q --wait load file:/home/media/playlists/radio
mpc -q play 3lsof -p $(pidof forked-daapd) |wc -lShairport-sync repository: https://github.com/mikebrady/shairport-sync It seems to me that shairport-sync sends the TCP-RST due to timeout. It uses in dacp.c
struct timeval tv;
tv.tv_sec = 0;
tv.tv_usec = 500000;
if (setsockopt(sockfd, SOL_SOCKET, SO_RCVTIMEO, (const char *)&tv, sizeof tv) == -1)
debug(1, "dacp_send_command: error %d setting receive timeout.", errno);In wireshark I can see that the RST-packet sends 0.5 sec after shairport-sync receives the ACK for
GET /ctrl-int/1/playstatusupdate?revision-number=2 HTTP/1.1One can wonder why forked-daapd does not answer this GET in less then 0.5 seconds?
ejurgensen
commented
4 years ago One can wonder why forked-daapd does not answer this GET in less then 0.5 seconds?
Because playstatusupdate with revision number 2+ is not a normal request, it is a long poll. The idea is that if there is play status change then the request is replied. So the request can hang for a pretty long time. Having a 0.5 second timeout on that request doesn't make sense, so not sure why that is. I am pretty sure the same applies to iTunes, though I haven't tested that in a while.
In any case I was still unable to reproduce, for some reason my shairport-sync is not making those requests at all. However, by mocking the requests with curl, cancelling with ^C + using Valgrind I can see that a memory leak is reported. So like your results it would indicate that there is some cleanup that isn't done. Debugging that requires some extra effort, since forked-daapd uses libevent for this stuff, but I am looking into it. I can probably do something to avoid the memleak, and then you can test if it also solves your issue.
ejurgensen
commented
4 years ago And here is branch where I have made some protection against repeated logging: https://github.com/ejurgensen/forked-daapd/tree/logavoidrepeat1
ejurgensen
commented
4 years ago I have now added a commit 4ecef8fa345dadde4cecfd08856abdd1f12e5c9d to the same branch with a possible fix for the memleak. Let me know if it also fixes the issue with the open files.
tomgadow
commented
4 years ago Thanks for your quick effort! Sorry, I was not prepared for that. I am away over the weekend and will test during next week.
jorbas
commented
4 years ago I'm encountering the same problem. Using the branch mentioned, the opened sockets is still increasing.
Once they fill up I'll report back with the logging situation.
EDIT: Log doesn't explode but CPU does go to 100% and the web UI and remotes are unresponsive.
tomgadow
commented
4 years ago logavoidrepeat1 does not log anything when it reaches the "Too many open files"-case above. The CPU goes up to 100% and the open file count holds at 1205 as before. I would expect at least one error message.
If I then try to change the song the next CPU goes up to 100% and I get an error in the log:
[ LOG] mpd: Error occured 24 (Too many open files) on the listener.
[...] ^^^^^^^^^-- this line repeats 14 times
[ LOG] mpd: Error occured 24 (Too many open files) on the listener.
[ LOG] mpd: (LOGGING SKIPPED - above log message is repeating)
[ LOG] mpd: Error executing command 'next': Failed to skip to next songSo yes the logging has changed to the better.
tomgadow
commented
4 years ago Here is the issue I opened on shairport-sync: https://github.com/mikebrady/shairport-sync/issues/953
ejurgensen
commented
4 years ago I suppose the CPU issue is because some other part of forked-daapd starts looping when the open file limit is reached. So it would be interesting to know what part that is. I've added a commit to the branch that also has log protection on debug level, so if you could try with that + set the log level to debug it might be possible to identify. I suggest you keep an eye on it while testing, because the log limiter won't stop the logging if multiple lines start repeating.
The main task is of course still to figure out why those files are not closed. I'm not sure how to do that, except by me taking another stab at reproducing. My shairport-sync isn't making those requests, but maybe I just need to change some setup/config to enable them.
jorbas
commented
4 years ago This isn't with the latest debug log protection, but this is all the logs show:
[2020-01-08 20:17:09] [DEBUG] dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
[2020-01-08 20:17:09] [DEBUG] player: Player status: stopped
[2020-01-08 20:17:09] [DEBUG] dacp: DACP request: '/ctrl-int/1/getspeakers'
[2020-01-08 20:17:09] [DEBUG] dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=2'
[2020-01-08 20:17:10] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:10] [DEBUG] dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
[2020-01-08 20:17:10] [DEBUG] player: Player status: stopped
[2020-01-08 20:17:10] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:10] [DEBUG] dacp: DACP request: '/ctrl-int/1/getspeakers'
[2020-01-08 20:17:10] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:10] [DEBUG] dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=2'
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: Error from accept() call: Too many open files
[2020-01-08 20:17:12] [ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[2020-01-08 20:33:25] [DEBUG] dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
[2020-01-08 20:33:25] [DEBUG] player: Player status: stopped
[2020-01-08 20:33:25] [DEBUG] dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
[2020-01-08 20:33:25] [DEBUG] player: Player status: stoppedIf it is any help to reproducing this problem on your end, this is my shairport-sync config:
general =
{
name = "Lounge";
interpolation = "soxr";
output_backend = "alsa";
mdns_backend = "avahi";
volume_control_profile = "standard";
};
sessioncontrol =
{
allow_session_interruption = "yes";
};
alsa =
{
output_device = "hw:IQaudIODAC";
mixer_control_name = "Digital";
use_hardware_mute_if_available = "yes";
disable_standby_mode = "auto";
};
metadata =
{
enabled = "no";
include_cover_art = "no";
};And my forked-daapd config:
general {
uid = "forked-daapd"
logfile = "/var/log/forked-daapd.log"
loglevel = debug
ipv6 = no
db_path = "/var/cache/forked-daapd/songs3.db"
cache_path = "/var/cache/forked-daapd/cache.db"
}
library {
name = "Home Music"
directories = { "/srv/music" }
podcasts = { "/Podcasts" }
audiobooks = { "/Audiobooks" }
compilations = { "/Compilations" }
compilation_artist = "Various Artists"
allow_modifying_stored_playlists = true
default_playlist_directory = "/srv/music/Playlists"
}
audio {
type = "disabled"
}Neither -d 5 nor -d 4 got the CPU to 100%. I think the debug writing in the terminal slows down the loop.
Here follow two cycles of debug output (-d 4) which repeats and repeats and repeats.
Hope this helps.
Tom
[DEBUG] mpd: MPD message: stats
[DEBUG] db: Starting query 'SELECT COUNT(*), SUM(song_length), COUNT(DISTINCT songartistid), COUNT(DISTINCT songalbumid) FROM files f WHERE f.disabled = 0;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'start_time';'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'db_update';'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] mpd: MPD message: status
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] player: Player status: playing
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] db: Running query 'SELECT COUNT(*) FROM queue;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] db: Running query 'BEGIN TRANSACTION;'
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE id = 51744 ORDER BY pos;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] db: Running query 'END TRANSACTION;'
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Fetch by pos: pos (1) relative to item with id (51744)
[DEBUG] db: Running query 'BEGIN TRANSACTION;'
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Fetch by pos: pos (1) relative to item with id (51744)
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Running query 'SELECT pos FROM queue WHERE id = 51744;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] db: Fetch by pos: item (51744) has absolute pos 0
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE pos = 1 ORDER BY pos;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] db: Fetch by pos: fetched item (id=51745, pos=1, file-id=10137)
[DEBUG] db: Running query 'END TRANSACTION;'
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Fetch by pos: fetched item (id=51745, pos=1, file-id=10137)
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] mpd: MPD message: stats
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Starting query 'SELECT COUNT(*), SUM(song_length), COUNT(DISTINCT songartistid), COUNT(DISTINCT songalbumid) FROM files f WHERE f.disabled = 0;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'start_time';'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'db_update';'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] mpd: MPD message: status
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] player: Player status: playing
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Running query 'SELECT COUNT(*) FROM queue;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Running query 'BEGIN TRANSACTION;'
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE id = 51744 ORDER BY pos;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] db: Running query 'END TRANSACTION;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Fetch by pos: pos (1) relative to item with id (51744)
[DEBUG] db: Running query 'BEGIN TRANSACTION;'
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Fetch by pos: pos (1) relative to item with id (51744)
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Running query 'SELECT pos FROM queue WHERE id = 51744;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Fetch by pos: item (51744) has absolute pos 0
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE pos = 1 ORDER BY pos;'
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
[DEBUG] db: Fetch by pos: fetched item (id=51745, pos=1, file-id=10137)
[DEBUG] db: Running query 'END TRANSACTION;'
[ WARN] event: Error from accept() call: Too many open files
[DEBUG] db: Fetch by pos: fetched item (id=51745, pos=1, file-id=10137)
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: Error from accept() call: Too many open files
[ WARN] event: (LOGGING SKIPPED - above log message is repeating)
mikebrady
commented
4 years ago Thanks to @tomgadow for bringing this to my attention. Let me look into the problem over the next few days.
mikebrady
commented
4 years ago Thanks indeed to @tomgadow for such an exemplary bug report!
I tried updating my shairport-sync to see if I could reproduce, but unfortunately couldn't. I also didn't see shairport-sync make those dacp requests. Do you have any pointers on steps to reproduce?
Shairport Sync will query the dacp status if it is built with support for the dbus, MPRIS or MQTT interfaces, specified with the --with-dbus-interface, --with-mpris-interface and --with-mqtt-client configuration flags respectively. This is necessary because these interfaces offer some remote control facilities and so Shairport Sync needs to be aware of the state and connectivity of the player.
The 0.5 second timeout used by Shairport Sync was chosen somewhat arbitrarily. It was long enough not to cause problems with iTunes or iOS (and also the newer macOS Music app) and short enough to allow for a quick reaction to the disappearance of the player from the net. It would be safe to change that to, say, 3 seconds, as the setting does not affect any other connections. I did not try it with forked-daapd, I'm afraid.
If you are going to experiment with Shairport Sync, I suggest you switch to the latest development branch – it has an extra remote command for setting the volume.
ejurgensen
commented
4 years ago Thanks for the info, I will try with those build settings + the dev branch. I think it is high priority to have forked-daapd work with shairport-sync, so it is great to hear from you directly @mikebrady.
It would be safe to change that to, say, 3 seconds, as the setting does not affect any other connections.
I don't think that will help with this problem. forked-daapd (and iTunes, I think?) treat /ctrl-int/1/playstatusupdate with revision number 2 as a long poll, so they don't return with a reply before there is a change to playback status. So it is a way of pushing an update from the player to the speaker (or to the remote).
I'm not sure what the indended use of playstatusupdate is for shairport-sync, but if you need to make standard request for playback status you just need to use revision number 1 instead of 2. Or I think you can also just not use any revision number.
mikebrady
commented
4 years ago Thanks @ejurgensen. Agreed on the priority – I am a big admirer of your work, and apologies for not testing against it.
I was not aware of the special significance of revision number 2. I understood that 1 returned the full status and any other revision number would return a status of 200 if something had changed along with a new revision number, sent as a cmsr token, to be used for the next query.
If nothing had changed, some other code (403 perhaps?) was returned and one used the same revision number for the next query.
mikebrady
commented
4 years ago @ejurgensen, is it possible that forked-daaapd could return a cmsr token value of 2 in response to a playstatusupdate request?
ejurgensen
commented
4 years ago Same to you, shairport-sync is great!
Yes, forked-daapd will indeed return a cmsr of 2 or more. You can see how these requests are handled here: https://github.com/ejurgensen/forked-daapd/blob/master/src/httpd_dacp.c#L2229
It's been a while since I worked with this part, but here is how I recall remotes normally use playstatusupdate:
The reply is always a 200 and the fields in the reply are the same (see make_playstatusupdate).
How is shairport-sync using playstatusupdate? Is it polling at regular intervals?
mikebrady
commented
4 years ago Thanks for the clarification. Yes indeed, Shairport Sync polls at regular intervals, as I didn't know the significance of the 2.
Okay, so let me do a little bit of checking and revert to you.
ejurgensen
commented
4 years ago Thanks to your instructions I was now able to reproduce the problem. It seems clear that the connection is not cleaned up. @tomgadow, you can probably also see that there is no logging of "Update request: client closed connection", and that means that libevent didn't register the disconnect.
Drilling down, it looks like there are two parts to the issue:
* Not sure if it keeps making them 24/7? If so that means a quarter of million (60 x 60 x 24 x 3) daily requests are made by each shairport-sync speaker.
mikebrady
commented
4 years ago Thanks for the update.
Shairport Sync polls each second while playing and every three seconds when playing has stopped and while the remote control port does not completely reject requests. Furthermore, it times out after a period of inactivity, maybe 15 minutes.
The long poll available for revision number 2 is certainly something to look at – it has the potential to greatly simplify this whole arrangement. Meantime, the quick-fix conservative approach for Shairport Sync is to avoid sending a cmsr value of 2 – I'll do that this evening.
I have not yet checked, but do iOS or iTunes/Music return a cmsr of 2 in response to a request with revision number 1? My guess is that 2 is never returned. That would account for why this issue does not arise with iOS or iTunes/Music.
ejurgensen
commented
4 years ago It is not just the value 2, it is all values above 1. There is no special treatment of 2 in itself. Both iTunes and forked-daapd can and will return cmsr values higher than 2. I will test with iTunes later to confirm.
mikebrady
commented
4 years ago Hmm. Just a quick check using macOS Music as the client using a slightly hacked development version of dacp.c:
case 'cmsr': // revision number
t = sp - item_size;
debug(1," Revision Number sent: %u, received: %u", revision_number, ntohl(*(uint32_t *)(t)));
if (revision_number == 1) {
revision_number = 2;
debug (1,"Setting revision number to 2.");
} else
revision_number = ntohl(*(uint32_t *)(t));
break;
No sign of either the long poll or any timeout problem.
19.919584674 "rtsp.c:1000" Connection 2: SETUP DACP-ID "CDB5BB07DC38F7E9" from 192.168.2.4 to 192.168.2.30 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
0.102427201 "dacp.c:627" Revision Number sent: 1, received: 11
0.001451989 "dacp.c:630" Setting revision number to 2.
1.041940870 "dacp.c:627" Revision Number sent: 2, received: 11
12.733686602 "dacp.c:627" Revision Number sent: 11, received: 14
155.578706099 "dacp.c:627" Revision Number sent: 14, received: 17I'm afraid I'm somewhat mystified. Maybe I'm doing something really dense – I'll check later.
ejurgensen
commented
4 years ago I have now tested with iTunes (I assume it behaves like Music) using Wireshark, and I think I can explain what you are observing, and why it is in a way working with iTunes and Music.
So, as you know, the response to your initial request from both servers has a cmsr value that you are supposed to use as a revision number for the next request. This value can be 2 or something else, that doesn't make a difference to what happens next.
shairport-sync will make the next request, and what happens then depends on the server: iTunes will return a 403 Forbidden, and forked-daapd will not reply within the timeout because it is a long poll. Note that the 403 doesn't mean "nothing changed", it actually means forbidden. That is because iTunes doesn't accept the request. You can check that by dumping the traffic between Remote and iTunes: Remote doesn't get a 403, iTunes accepts the request and iTunes "hangs", just like forked-daapd.
However, despite the 403's it still works for shairport-sync and I think that is due to the below.
shairport-sync will continue polling with the same revision number, and it will get 403's/timeouts. For iTunes, however, at some point it will get an actual reply with a new cmsr. If I understand correctly, shairport-sync interprets this as a status update, and indeed it is, because the reason iTunes now gave an answer was that the server side revision number increased due to an event.
The thing is that iTunes only authorizes the request if you call it with the correct, current revision number. If you call it with any other revision number it will return which one to use (via the cmsr tag). And that is what happened after the server side event, the revision number was no longer the current, so iTunes returned a new one.
I don't know how you would get iTunes to accept the request, but since there are non-Apple Android remotes I suppose it must be possible.
mikebrady
commented
4 years ago Thanks for that. It explains the significance of the revision numbers but it does not explain the absence of the long poll, which is the crux of the problem here.
For that, I have a conjecture – the player has two different modes. For a regular remote control (e.g. the Remote app) to work with iTunes, it has to be PIN validated, but Shairport Sync does not use PIN validation. Instead, dacp traffic seems to be accepted from Shairport Sync without validation or Session ID since it is coming from the output device.
Therefore, it may be that the client has a mode for interacting with PIN-validated remotes like Remote and this mode includes the long poll behaviour. The client has another mode for interacting with the output device, e.g. Shairport Sync, but this mode does not provide the long poll.
Further, I'm guessing that Forked Daapd has the same behaviour whether the remote device is PIN-validated or not.
If I'm right, then two things follow:
Fixing the problem from the Shairport Sync perspective is easy – it is simply necessary to remove the timeout. The only implications to check for are in cases where the player (iOS/iTunes/Forked Daapd/Music, etc.) suddenly disappears.
Strictly for verisimilitude only, Forked Daapd should take note of whether the remote device is PIN-validated or not and provide a long poll only when PIN-validated.
mikebrady
commented
4 years ago I just pushed an update to the development branch of Shairport Sync removing the timeout. Hopefully it addresses the immediate problem.
ejurgensen
commented
4 years ago Yes I agree, you could remove the timeout. I haven't tested your commit, but is shairport-sync ok with the dacp thread blocking on dacp_send_command()? I imagine that could be a problem, so perhaps you would need to implement async/non-blocking requests?
I don't think it is likely that iTunes/Music has different modes of operation, that would entail bad design for number of reasons:
You are right that iTunes does authorize Remotes and speakers in different ways. Remotes are auth'ed with pairing + session-id's, and speakers with active remote. I haven't come across other speakers that use playstatusupdate. If such exist it would be interesting to catch the traffic from them.
If I was you I would still try using rev number 1. That will also avoid the 403's from iTunes, and I don't suppose you are interested in them?
mikebrady
commented
4 years ago 19.919584674 "rtsp.c:1000" Connection 2: SETUP DACP-ID "CDB5BB07DC38F7E9" from 192.168.2.4 to 192.168.2.30 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003. 0.102427201 "dacp.c:627" Revision Number sent: 1, received: 11 0.001451989 "dacp.c:630" Setting revision number to 2. 1.041940870 "dacp.c:627" Revision Number sent: 2, received: 11 12.733686602 "dacp.c:627" Revision Number sent: 11, received: 14 155.578706099 "dacp.c:627" Revision Number sent: 14, received: 17
Just referring back to this; perhaps I should have explained. Each of these line 627 messages was output when a status request was accepted. The revision numbers being sent were always the correct ones. It's just that when nothing had changed -- and thus the change the revision number referred to hadn't happened yet -- the player sent back a 403 rather then entering a long poll.
As I outlined in the previous post, I guess the difference in behaviour between immediately returning a 403 or entering a long poll is due to different modes of operation within the player because of the different styles of access of the remote status requester.
ejurgensen
commented
4 years ago Yes, I understood the output, I saw the same behavior. I don't know if you saw the post I just made, but as you can see I don't believe that long polling is only for remotes.
mikebrady
commented
4 years ago Yes I agree, you could remove the timeout. I haven't tested your commit, but is shairport-sync ok with the dacp thread blocking on dacp_send_command()? I imagine that could be a problem, so perhaps you would need to implement async/non-blocking requests?
Hmm. I'd really like to avoid this. You're right though. Long polling is blocking. It means that Shairport Sync could not send commands to Forked Daapd, so that's not going to work.
I don't think it is likely that iTunes/Music has different modes of operation, that would entail bad design for number of reasons:
- Why would they choose a design that actively prohibits speakers from long polling? Long polling is superior when it comes to lag, network and overhead.
Well, they don't prevent it – it seems to be available, but it seems it is available only if PIN-validated. And long polling means you can't, for example, use a single thread to deal with traffic.
You are right about the lag. The network issue is moot – iTunes generates lots of repetitive traffic, e.g. the OPTIONS message. Any by comparison with the overall traffic it is a non-issue.
- Why would they decide to use 403 to signify "no change"? That is a horrible choice, because it makes it impossible for the client to distinguish between "no change" and an actual auth error. Also the more logical way of replying "no change" would be with a 200 and a few dmap tags.
Code 403 can be used to indicate that the server is refusing to take action, which is exactly the case here. Remember that the source has to be the output device itself, so authentication isn't an issue. If the source of the request has a different IP number, is does not get back 403 (offhand, I can't remember what it is, but it's different). Anyway, authentication issues would be signalled with with a 401 code, I'd have thought. My guess is that it's a legacy behaviour.
- Speakers can already short poll just by using revision number 1 every time, so why would they even make the above changes?
Revision Number 1 always responds with a complete status, whether there have been changes or not. This means that the remote device has to sift through it to see if any actual change has occurred. It's not a big deal to accommodate this in something like Shairport Sync but would be an energy issue on a power-constrained device like a battery powered remote.
- Having the same endpoint act differently based on who you are, and not on explicit request parameters, seems like bad design to me.
Well it does explain what is actually out there. It does seem that the endpoint acts differently depending on how you interact with it.
You are right that iTunes does authorize Remotes and speakers in different ways. Remotes are auth'ed with pairing + session-id's, and speakers with active remote. I haven't come across other speakers that use playstatusupdate. If such exist it would be interesting to catch the traffic from them.
I haven't come across them either – I'm just trying to make sense, and take advantage, of what's out there now.
If I was you I would still try using rev number 1. That will also avoid the 403's from iTunes, and I don't suppose you are interested in them?
Yes. Overall, it seems as if Forked Daapd behaves differently from iOS/iTunes/Music. What I might have to do is make a special case for Forked Daapd only – use Revision Number 1 for it always and continue to use the existing system for all other players.
Yes, I understood the output, I saw the same behavior. I don't know if you saw the post I just made, but as you can see I don't believe that long polling is only for remotes.
As I mentioned above, I think that remotes get long polling because they are PIN-validated.
ejurgensen
commented
4 years ago Ok, maybe we have different viewpoints here :-)
Well, they don't prevent it – it seems to be available, but it seems it is available only if PIN-validated.
I don't it is plausible that Apple wants speakers to PIN validate (they often have no UI) just to do long polling. So I still don't believe in the two modes of operation. I think the reason for the 403 is very simple, either there's some additional data iTunes wants, or there is simply a bug in iTunes that isn't a priority because speakers using playstatusupdate are rare.
And long polling means you can't, for example, use a single thread to deal with traffic.
You can absolutely use a single thread, but you would need an event loop.
Code 403 can be used to indicate that the server is refusing to take action, which is exactly the case here.
I don't really agree that it is the case here. In any case you are not supposed to try again if you get a 403, which is what shairport-sync is doing.
This means that the remote device has to sift through it to see if any actual change has occurred
That is not necessary, you can just check if the cmsr changed.
mikebrady
commented
4 years ago Great stuff, thanks.
I don't it is plausible that Apple wants speakers to PIN validate (they often have no UI) just to do long polling.
You may be right, of course, but the behaviour is there a long time.
you are not supposed to try again if you get a 403, which is what shairport-sync is doing.
That's a good point.
you can just check if the
cmsrchanged.
Sure, but you have to parse it first.
Sigh. It would be great to have a spec... :)
mikebrady
commented
4 years ago I just pushed another update to the development branch of Shairport Sync removing the timeout.
Hopefully it addresses the immediate problem. It works nicely for me, and I'd be grateful if you would give it a try.
ejurgensen
commented
4 years ago I have tried with your update, and it works very nicely. I have tested it against both forked-daapd master and the branch logavoidrepeat1 I made to fix the issues reported by @tomgadow, and it works with both. I have also added some commits to the branch, one includes the libevent workaround mentioned above that should protect against missing cleanup (too many open files), and the other makes sure that forked-daapd increases cmsr after playback events, even if there are no current update requests (so like it appears iTunes does).
So I'm optimistic the issue is about to be solved, but it would of course be great if you could confirm @tomgadow
tomgadow
commented
4 years ago Both fixes fixed the "Too many open files"-issue for me.
@mikebrady wrote:
Shairport Sync will query the dacp status if it is built with support for the dbus, MPRIS or MQTT interfaces, specified with the --with-dbus-interface, --with-mpris-interface and --with-mqtt-client configuration flags respectively.
This seems to match. Debian uses all three config flags. Myself I turned off mqtt. I wasn't to keen on installing mqtt-dev libraries.
@ejurgensen wrote:
you can probably also see that there is no logging of
Update request: client closed connection, and that means that libevent didn't register the disconnect.
This is correct. There is no string client closed connection in any of my log dumps.
For me, the issue reproduces with libevent 2.0 (Stretch), but not with libevent 2.1.8 (Buster).
It is interesting that you mention libevent. I checked and had three libevent packages installed on my Debian testing.
ii libevent-2.1-6:amd64 2.1.8-stable-4 amd64 Asynchronous event notification library
ii libevent-2.1-7:amd64 2.1.11-stable-1 amd64 Asynchronous event notification libraryand
libevent-2.0-5:amd64 2.0.21-stable-3I checked forked-daapd before and after removing libevent v2.0.21 and it used in both cases
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/libevent_pthreads-2.1.so.7", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7", O_RDONLY|O_CLOEXEC) = 3which is linked to
/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7 -> libevent-2.1.so.7.0.0which is part of Debian package libevent-2.1-7 means libevent v2.1.11.
I checked my log files and found the first Too many open files on 2019-11-24.
The latest forked-daapd (v26.4) in Debian testing is from 2019-01-07.
Shairport-sync v3.1.7 came 2018-01-26 and v3.2.1 2018-09-15. I found out that v3.2 is the first version which has this issue but was never in Debian testing so I take v3.2.1 as a reference.
You see the dates don't add upp. I should have experienced the problems att least since somewhere in 2018 and not in late 2019.
Libevent v2.1.8 came 2017-08-06 and v2.1.11 2019-11-17. I found in the dpkg-logfile that I installed libevent v2.1.11 on 2019-11-24. The same day my problems began. So libevent can play a role as culprit in this case. There are maybe some changes in connection handling between v2.1.8 and v2.1.11?
I tested the latest development shairport-sync against logavoidrepeat1 forked-daapd.
Result: The "Too many open files"-issue has gone. Shairport-sync seems to ask playstatusupdate every time with revision-number=1 and gets an answer directly:
3.3.6d5-OpenSSL-Avahi-ALSA-pa-dummy-stdout-pipe-soxr-metadata-dbus-mpris-sysconfdir:/tmp/s-s/etc
[...]
0.679611205 "dacp.c:253" dacp_send_command: "getproperty?properties=dmcp.volume".
0.001062717 "dacp.c:357" dacp_send_command: 0.001207 seconds, response code 200, command "getproperty?properties=dmcp.volume".
0.000143536 "dacp.c:253" dacp_send_command: "getspeakers".
0.000533782 "dacp.c:357" dacp_send_command: 0.000633 seconds, response code 200, command "getspeakers".
0.000040008 "dacp.c:571" Scan Result: 200, Bad Scan Count: 0, Idle Scan Count: 0.
0.000012784 "metadata_hub.c:137" Metadata_hub write lock acquired.
0.000009522 "metadata_hub.c:148" Metadata_hub write lock unlocked.
0.000019520 "metadata_hub.c:137" Metadata_hub write lock acquired.
0.000014965 "metadata_hub.c:148" Metadata_hub write lock unlocked.
0.000121781 "dacp.c:253" dacp_send_command: "playstatusupdate?revision-number=1".
0.000898884 "dacp.c:357" dacp_send_command: 0.001000 seconds, response code 200, command "playstatusupdate?revision-number=1".
0.000037280 "metadata_hub.c:137" Metadata_hub write lock acquired.
0.000012970 "dacp.c:766" DACP Composite ID seen
0.000008956 "dacp.c:734" DACP Track Name seen
0.000012589 "dacp.c:742" DACP Artist Name seen
0.000008515 "dacp.c:750" DACP Album Name seen
0.000011361 "dacp.c:758" DACP Genre seen
0.000012128 "dacp.c:786" DACP Song Time seen: "0" of length 4.
0.000019676 "metadata_hub.c:148" Metadata_hub write lock unlocked.The open file count is stable at 265 files.
I tested shairport-sync v3.3.5 against the latest logavoidrepeat1 forked-daapd.
Result: The "Too many open files"-issue has gone:
0.651399757 "dacp.c:246" dacp_send_command: "getproperty?properties=dmcp.volume".
0.001070665 "dacp.c:348" dacp_send_command: 0.001211 seconds, response code 200, command "getproperty?properties=dmcp.volume".
0.000142414 "dacp.c:246" dacp_send_command: "getspeakers".
0.000480158 "dacp.c:348" dacp_send_command: 0.000577 seconds, response code 200, command "getspeakers".
0.000028375 "dacp.c:545" Scan Result: 200, Bad Scan Count: 0, Idle Scan Count: 0.
0.000012389 "metadata_hub.c:137" Metadata_hub write lock acquired.
0.000009762 "metadata_hub.c:148" Metadata_hub write lock unlocked.
0.000013927 "metadata_hub.c:137" Metadata_hub write lock acquired.
0.000009512 "metadata_hub.c:148" Metadata_hub write lock unlocked.
0.000106541 "dacp.c:246" dacp_send_command: "playstatusupdate?revision-number=5".
0.356714817 "rtp.c:371" New latency detected: 99142, sync latency: 88117, minimum latency: 0, maximum latency: 0, fixed offset: 11025.
0.173039573 "dacp.c:287" dacp_send_command: receiving error 11: "Resource temporarily unavailable".
0.000109634 "dacp.c:348" dacp_send_command: 0.529949 seconds, response code 495, command "playstatusupdate?revision-number=5".
0.237026178 "player.c:1556" soxr_oneshot execution time in microseconds: mean, standard deviation and max for 379 interpolations in the last 1250 packets. 809.2, 187.6, 1117.0.Inspite of shairport-sync's 0.5 sec timeout during playstatusupdate paket with revision-number=5 the open file count stays stable ±1 file.
I tested the latest development shairport-sync against the latest logavoidrepeat1 forked-daapd.
Result: The "Too many open files"-issue has gone. This was expected :-).
Thanks a lot guys! You are great!
Now we have all time in the world to decide if shairport-sync should keep "revision-number=1" in the future or should go back to 1+ and save a tiny bit of bandwith and delay. As I understand it is not easy to decide whats right or wrong without a written specification. I hope some speaker device in the future will show us the way :-).
Greetings! Tom
ejurgensen
commented
4 years ago Thanks for excellent feedback, that is very much appreciated. I have also tested the changes with the remotes I had available, and I didn't find any regressions. So I have now merged the fixes in the branch into forked-daapd's master.
Also many thanks to you @mikebrady, hope to get in touch with you again some other time, we probably have many shared interests and issues. Airplay 2 for instance :-)
mikebrady
commented
4 years ago Thanks @tomgadow and @ejurgensen. It was a pleasure and a learning experience to help to resolve this.
Hi!
TLDR;
shairport-sync (at least version 3.3.5) can block forked-daapd. Forked-daapd will in this case fill the logfile and the harddisk with GBs of the same error message in a couple of hours.
The long story
My machine runs Debian testing with all updates and forked-daapd is installed in version 26.4. I tested the latest version (27.0), too with the same problem.
Sometimes forked-daapd seems to "crash". It uses 100% CPU time and in the logfile one can found:
In this case it is not possible to connect to forked-daapd with new commands but if I catch the error early I can stop the running song with an already connected client. Everything is then back to normal.
If I did not catch the error in time my connected client will loose the connection and I only can kill the forked-daapd process.
The warning repeats a couple of million times per minute so it's easy to fill a 100 GB harddisk within a couple of hours.
The open file limit for the process is:
And during the "crash" I can see the process has really reached this limit:
I can see that the file count goes up with about 40 files every minute and resets with every new song playing to about 250 open files. Because of this reset at the start of a new media file I only see the problem if I am listening to an internet stream.
Then the lsof list has about 1000 entries like this one:
I got the latest forked-daapd (27.0) from GitHub and tested:
And started as root:
27.0 has the same problem - the open files counted up. Strace did not help either. The output was quiet after everything had startet but the open files counted up.
I have three clients in the network.
After I stopped shairport-sync 3.3.5 everything worked fine. The open files count stopped completely.
I checked with tcpdump and can see that shairport-sync 3.3.5 opens 3 new connections about every 1-2 seconds:
shairport-sync opens a new connection for every question - I don't see this behaviour with 2.8.6. That version seems to reuse the connections - The first two connections get answered and closed via FIN, ACK-sequence.
The third connection gets canceled every time via RST, ACK sent from shairport-sync.
I would say the third connection is the culprit. Maybe forked-daapd does not catch the reset flag and keeps the connection/file open?
Can you confirm this?
Would it be possible for you to implement that
This would be great :-)
Thanks for your help!
Tom
PS: I will investigate further on the shairport-sync side and keep you updated.