Cannot select speakers in Remote

[andyjenkinson]

Opening a new issue, the symptoms are similar to those described in issue #86 but this appears to be different, not really an enhancement.

Basically what happens is, I open up Remote (iOS8), hit play on a song, and the "now playing" dialog appears very briefly but then immediately exists. There is just enough time to bring up the AirPlay dialog showing the available speakers (local, and two remote shairport-sync speakers) but only if you're very lucky is there enough time to select one. It takes ~50 tries.

Local audio is not connected on this server, but the shairport-sync targets do work fine (the iphone itself can select them).

Here is the forked-daapd log:

[2015-01-29 11:47:41] raop: OPTIONS request failed in session startup: 0 (null) [2015-01-29 11:47:41] player: Cannot start playback: no output started [2015-01-29 11:47:41] dacp: Could not start playback [2015-01-29 11:47:44] raop: OPTIONS request failed in device probe: 0 (null) [2015-01-29 11:47:44] dacp: Speakers de/activation failed!

Previously I thought this only happened after the local audio had been selected (see issue #86), but it is happening every day, with the only output target selected being the same AirPort device. It's possible some details of the connection change in between (e.g. IP address, or even IPv6) but I've no idea if this contributes to the cause. I can't isolate the cause.

If the problem is with the airplay target not handling the request properly, I wonder if this error condition could be handled in a way that doesn't trigger the behaviour I describe?

[ejurgensen]

When establishing a connection the OPTIONS request is the initiating request from forked-daapd to the device. What the log says is that there is no reply, not even an error message. So something network related seems likely. If the target changes ip address or port without announcing the change that could be the cause, but I don't see why it would do that?

You mention that 1 out of 50 times you are able to select a speaker, and then it works. I'm a bit puzzled by that, because selecting the speaker shouldn't make a difference to how forked-daapd initiates the connection. Some remotes (eg. Remote for iPad, TunesRemote-SE and some of the Android remotes) allow selection of speakers also when there is no playback. If you have the option of testing with one of these it would be interesting to know if that makes a difference.

[andyjenkinson]

Network issues are indeed possible, it seems strange that the IP address would change so frequently without shairport noticing, but you never can be sure when it comes to networks. Bear in mind devices can have multiple interfaces and IP addresses too. The other possibility that occurred to me is that the Remote app remembers the speakers and tries to get forked-daapd to play to them even though they no longer exist. I’m sure you’ll know better than I if that is possible, I don’t know what identifier a set of speakers is known by. Does forked-daapd look for announced services before playback? If so then I guess the problem would have to be that the speaker is announcing its service on an IP address it doesn’t have, right?

In fairness, failures are always possible in networked architectures, ideally they would be dealt with gracefully. What that means for forked-daapd when it tries to play to a missing device is, I can’t really say - possibly similar behaviour as if the local audio is selected and does not work? That is, go down the list of speakers until a working one is found?

Regarding the "1 in 50” comment, what I meant is that I have found that it is technically possible to select a different speaker before the application acts on the error. This is only possible if you are very quick and the network is slow; it’s rare to succeed, but I have managed to a couple of times. I would certainly expect this behaviour to change with one of those other apps you mention if they have a way to select the speakers before starting playback. It’s a bit annoying that the only way to do it in the iPhone's Remote app is to hit play...

On 30 Jan 2015, at 22:09, ejurgensen notifications@github.com wrote:

When establishing a connection the OPTIONS request is the initiating request from forked-daapd to the device. What the log says is that there is no reply, not even an error message. So something network related seems likely. If the target changes ip address or port without announcing the change that could be the cause, but I don't see why it would do that?

You mention that 1 out of 50 times you are able to select a speaker, and then it works. I'm a bit puzzled by that, because selecting the speaker shouldn't make a difference to how forked-daapd initiates the connection. Some remotes (eg. Remote for iPad, TunesRemote-SE and some of the Android remotes) allow selection of speakers also when there is no playback. If you have the option of testing with one of these it would be interesting to know if that makes a difference.

— Reply to this email directly or view it on GitHub.

[thorsteneckel]

Same here... I tried it with a raspbmc and the Mac OS X App 'Reflector'. I might get to test it with a ShAIRport (Raspberry) this week. I changed the log level of my forked-daapd to 'spam' and this is what I got:

[2015-02-07 19:25:32] [DEBUG]    httpd: Found query string
[2015-02-07 19:25:32] [DEBUG]     dacp: DACP request: /ctrl-int/1/getspeakers?session-id=100
[2015-02-07 19:25:33] [DEBUG]    httpd: Found query string
[2015-02-07 19:25:33] [DEBUG]     dacp: DACP request: /ctrl-int/1/setspeakers?speaker-id=0,0x10ddb1a713c7&session-id=100
[2015-02-07 19:25:33] [DEBUG]     dacp: Speaker id converted with ret 0, param 0,0x10ddb1a713c7, dec val 0.
[2015-02-07 19:25:33] [DEBUG]     dacp: Speaker id converted with ret 0, param 0x10ddb1a713c7, dec val 18544354333639.
[2015-02-07 19:25:33] [DEBUG]   player: Speaker set: 2 speakers
[2015-02-07 19:25:33] [DEBUG]   player: Set 0 device 18544354333639
[2015-02-07 19:25:33] [DEBUG]   player: Set 18544354333639 device 18544354333639
[2015-02-07 19:25:33] [DEBUG]   player: RAOP device AirPlay Speaker selected
[2015-02-07 19:25:33] [DEBUG]   player: Activating RAOP device AirPlay Speaker
[2015-02-07 19:25:33] [DEBUG]     raop: Building OPTIONS for AirPlay Speaker
[2015-02-07 19:25:33] [DEBUG]   player: Local audio selected
[2015-02-07 19:25:33] [ WARN]    event: event_del: event has no event_base set.
[2015-02-07 19:25:33] [  LOG]     raop: Reply CSeq does not match request CSeq: got 0 expected 1
[2015-02-07 19:25:33] [  LOG]     dacp: Speakers de/activation failed!
[2015-02-07 19:25:33] [DEBUG]    httpd: Found query string
[2015-02-07 19:25:33] [DEBUG]     dacp: DACP request: /ctrl-int/1/getspeakers?session-id=100
[2015-02-07 19:25:34] [DEBUG]    httpd: Found query string
[2015-02-07 19:25:34] [DEBUG]     dacp: DACP request: /ctrl-int/1/getproperty?properties=dmcp.volume&session-id=100
[2015-02-07 19:25:34] [DEBUG]   player: Player status: playing
[2015-02-07 19:25:34] [DEBUG]       db: Running query 'SELECT f.* FROM files f WHERE f.id = 1;'

I'm using a FreeBSD 10.1. My installation steps are documented in a gist: https://gist.github.com/thorsteneckel/c0610fb415c8d0486bce

[ejurgensen]

Some AirPlay targets don't return a proper sequence value (CSeq), I have previously seen this with AirFoil. Maybe Reflector just always returns 0? You can try changing line 1195 in raop.c like so: "if (reply_cseq < 0)" -> "if (reply_cseq <= 0)"

If this works, let me know, then I can look into making that change.

[thorsteneckel]

I changed the if condition as you proposed, but it didn't work out correctly. Seems that now the next execution of 'raop_check_cseq' fails :(

Here is what the log says:

[2015-02-08 14:17:11] [DEBUG]   ffmpeg: marker parser used 181 bytes (1448 bits)
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: marker=c4 avail_size_in_buf=52770
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: class=0 index=1 nb_codes=12
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: marker parser used 31 bytes (248 bits)
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: marker=c4 avail_size_in_buf=52737
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: class=1 index=1 nb_codes=251
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: marker parser used 181 bytes (1448 bits)
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: escaping removed 231 bytes
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: marker=da avail_size_in_buf=52554
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: component: 0
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: component: 1
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: component: 2
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: marker parser used 52322 bytes (418575 bits)
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: marker=d9 avail_size_in_buf=0
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: decode frame unused 0 bytes
[2015-02-08 14:17:11] [ INFO]   ffmpeg: max_analyze_duration 5000000 reached at 5015510 microseconds
[2015-02-08 14:17:11] [ WARN]   ffmpeg: Estimating duration from bitrate, this may be inaccurate
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: After avformat_find_stream_info() pos: 257359 bytes read:262144 seeks:0 frames:195
[2015-02-08 14:17:11] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 1;'
[2015-02-08 14:17:11] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 1 ;'
[2015-02-08 14:17:11] [DEBUG]       db: Running query 'SELECT f.* FROM files f WHERE f.id = 1;'
[2015-02-08 14:17:11] [DEBUG]  artwork: Artwork request for item 1 (01 Jeopardy.mp3)
[2015-02-08 14:17:11] [DEBUG]  artwork: Looking for artwork for group with persistentid 2558486014056832785
[2015-02-08 14:17:11] [DEBUG]    cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2558486014056832785 AND a.max_w = 600 AND a.max_h = 600;'
[2015-02-08 14:17:11] [DEBUG]    cache: Cache hit: SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2558486014056832785 AND a.max_w = 600 AND a.max_h = 600;
[2015-02-08 14:17:11] [DEBUG]  artwork: Group 2558486014056832785 found in cache with format 2
[2015-02-08 14:17:11] [DEBUG]     raop: Building OPTIONS for AirPlay Speaker
[2015-02-08 14:17:11] [ INFO]   player: Autoselecting AirPlay device AirPlay Speaker
[2015-02-08 14:17:11] [ WARN]    event: event_del: event has no event_base set.
[2015-02-08 14:17:11] [ INFO]     raop: No CSeq in reply, skipping check
[2015-02-08 14:17:11] [DEBUG]     raop: Local address: 192.168.178.75 (LL: no) port 20839
[2015-02-08 14:17:11] [DEBUG]     raop: Building ANNOUNCE for AirPlay Speaker
[2015-02-08 14:17:11] [  LOG]     raop: Reply CSeq does not match request CSeq: got 1 expected 2
[2015-02-08 14:17:11] [  LOG]   player: Cannot start playback: no output started
[2015-02-08 14:17:11] [DEBUG]   ffmpeg: Statistics: 262144 bytes read, 0 seeks
[2015-02-08 14:17:11] [  LOG]     dacp: Could not start playback
[2015-02-08 14:17:11] [DEBUG]   player: Player status: stopped
[2015-02-08 14:17:12] [DEBUG]    httpd: Found query string
[2015-02-08 14:17:12] [DEBUG]     dacp: DACP request: /ctrl-int/1/playstatusupdate?revision-number=3&session-id=100
[2015-02-08 14:17:12] [DEBUG]    httpd: Found query string

Regarding the following log line:

[2015-02-08 14:17:11] [ WARN]    event: event_del: event has no event_base set.

I found this (pretty old) issue in the original repo of forked-daapd: https://github.com/jasonmc/forked-daapd/issues/38

[ejurgensen]

The libevent error is nothing to be concerned about, it just means that there was delete request for a non-existing event (it was probably already deleted).

The problem is still CSeq: "Reply CSeq does not match request CSeq: got 1 expected 2". So Reflector apparently does support CSeq, but off-by-one compared to forked-daapd? I think you may be able to get away with disabling the check all-together, for instance by just making raop_check_cseq() always return 0.

[thorsteneckel]

 I think you may be able to get away with disabling the check all-together, for instance by just making raop_check_cseq() always return 0.

That worked for me. Nice - thanks a lot! I will create a fork of your repo for my purposes. Maybe there is a way to handle this behavior correctly in the future? This would be great.

[andyjenkinson]

I would think the "correct" way forward would be to contact the Reflector developer to figure out what is the correct behaviour.

[ejurgensen]

Yes, that would be the correct way, the rtsp spec says the server must echo the CSeq, so they should fix it in their end. However, this is not the first time I see this, so now I just changed forked-daapd to ignore the CSeq in the reply. I noticed that Reflector also returns the wrong CSeq to iTunes, and that iTunes just ignores it. So that's what I'm going to do too.

[thorsteneckel]

Thanks! I will check your changes the next day and drop some feedback. Would be cool to drop my fork of forked-daapd. :+1:

[dxlr8r]

Had troubles with shairport4w (http://sourceforge.net/projects/shairport4w/) and forked-daapd. Works with AirFoil though.

[ejurgensen]

I just took shairport4w for a spin, and it worked alright. So not sure what to do. I will need some clues on how to reproduce the problem.