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.1k stars 237 forks source link

D-link airplay speaker doesn't work #378

Closed otrojaramago closed 7 years ago

otrojaramago commented 7 years ago

Hi, I have four "D-link music everywhere " airplay compatible adapters. It works perfect only if they are running before starting forked-daapd. Pluging one of this adapters after the program is started makes the speakers appears and selectable, but throw an error and doesn't activates it. This is the log when failing: [2017-04-16 21:05:15] raop: Could not make OPTIONS request [2017-04-16 21:06:00] raop: OPTIONS request failed in device probe: 0 (null) [2017-04-16 21:06:00] dacp: Speakers de/activation failed!

And this when adapters powered before and working good: [2017-04-16 21:31:47] raop: Could not make OPTIONS request

ejurgensen commented 7 years ago

What version of forked-daapd are you using? The log indicates that it is not very recent. Not sure if upgrading will fix the problem, but it would be good if you would try that first and report back.

otrojaramago commented 7 years ago

Version: 22.0-2 I'm using openmediavault 3.0.70 and forked-daapd is the latest available in the repository

ejurgensen commented 7 years ago

That is more than two years old. I suggest you try to get in touch with the omv maintainer and request an update.

In the meantime, you could test if the problem is fixed if you have a platform where you are able to build from source.

otrojaramago commented 7 years ago

I'll try to build from pc to see if that solves the problem

otrojaramago commented 7 years ago

Today I have tried version 24 and same problem remains

ejurgensen commented 7 years ago

Can you set the log level to debug and post the relevant section from the log?

otrojaramago commented 7 years ago

Adapters already plugged:

[2017-04-17 23:51:24] [DEBUG] mdns: Avahi Browser: NEW service '48ee0c649791@AudioCast_Baño' type '_raop._tcp' proto 0 [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Browser: NEW service '48ee0c649791@AudioCast_Baño' type '_raop._tcp' proto 1 [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Browser: NEW service '48ee0c648d69@AudioCast_Dormitorio' type '_raop._tcp' proto 0 [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Browser: NEW service '48ee0c648d69@AudioCast_Dormitorio' type '_raop._tcp' proto 1 [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Browser: NEW service '48ee0c648de1@AudioCast_Salon' type '_raop._tcp' proto 0 [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Browser: NEW service '48ee0c648de1@AudioCast_Salon' type '_raop._tcp' proto 1 [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Browser (_touch-remote._tcp): no more results (CACHE_EXHAUSTED) [2017-04-17 23:51:24] [DEBUG] mdns: Group registering [2017-04-17 23:51:24] [DEBUG] mdns: Group uncommitted [2017-04-17 23:51:24] [DEBUG] mdns: Group registering [2017-04-17 23:51:24] [DEBUG] mdns: Group uncommitted [2017-04-17 23:51:24] [DEBUG] mdns: Group registering [2017-04-17 23:51:24] [DEBUG] mdns: Group uncommitted [2017-04-17 23:51:24] [DEBUG] mdns: Group registering [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Resolver: resolved service '48ee0c649791@AudioCast_Baño' type '_raop._tcp' proto 0, host dlinkap.local [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Resolver: resolved service '48ee0c649791@AudioCast_Baño' type '_raop._tcp' proto 1, host dlinkap.local [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Resolver: resolved service '48ee0c648d69@AudioCast_Dormitorio' type '_raop._tcp' proto 0, host dlinkap-3.local [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Resolver: resolved service '48ee0c648d69@AudioCast_Dormitorio' type '_raop._tcp' proto 1, host dlinkap-3.local [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Resolver: resolved service '48ee0c648de1@AudioCast_Salon' type '_raop._tcp' proto 0, host dlinkap-2.local [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Resolver: resolved service '48ee0c648de1@AudioCast_Salon' type '_raop._tcp' proto 1, host dlinkap-2.local [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Record Browser (dlinkap.local, proto 0): NEW record 192.168.9.157 for service type '_raop._tcp' [2017-04-17 23:51:24] [DEBUG] raop: Event for AirPlay device AudioCast_Baño (port 5002, id 48ee0c649791) [2017-04-17 23:51:24] [ INFO] raop: Adding AirPlay device 48ee0c649791@AudioCast_Baño: password: 0, encrypt: 1, metadata: 0, type AirPort Express 1 - 802.11g, address 192.168.9.157:5002 [2017-04-17 23:51:24] [DEBUG] db: Running query 'SELECT s.selected, s.volume FROM speakers s WHERE s.id = 80187247335313;' [2017-04-17 23:51:24] [ WARN] mdns: Ignoring announcement from dlinkap.local, address fe80::4aee:cff:fe64:9791 is link-local [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Record Browser (dlinkap.local, proto 1): no more results (CACHE_EXHAUSTED) [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Record Browser (dlinkap-3.local, proto 0): NEW record 192.168.9.167 for service type '_raop._tcp' [2017-04-17 23:51:24] [DEBUG] raop: Event for AirPlay device AudioCast_Dormitorio (port 5002, id 48ee0c648d69) [2017-04-17 23:51:24] [ INFO] raop: Adding AirPlay device 48ee0c648d69@AudioCast_Dormitorio: password: 0, encrypt: 1, metadata: 0, type AirPort Express 1 - 802.11g, address 192.168.9.167:5002 [2017-04-17 23:51:24] [ WARN] mdns: Ignoring announcement from dlinkap-3.local, address fe80::4aee:cff:fe64:8d69 is link-local [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Record Browser (dlinkap-3.local, proto 1): no more results (CACHE_EXHAUSTED) [2017-04-17 23:51:24] [DEBUG] mdns: Avahi Record Browser (dlinkap-2.local, proto 0): NEW record 192.168.9.165 for service type '_raop._tcp' [2017-04-17 23:51:24] [DEBUG] raop: Event for AirPlay device AudioCast_Salon (port 5002, id 48ee0c648de1) [2017-04-17 23:51:24] [ INFO] raop: Adding AirPlay device 48ee0c648de1@AudioCast_Salon: password: 0, encrypt: 1, metadata: 0, type AirPort Express 1 - 802.11g, address 192.168.9.165:5002 [2017-04-17 23:51:24] [ WARN] mdns: Ignoring announcement from dlinkap-2.local, address fe80::4aee:cff:fe64:8de1 is link-local

Adapter plugged after: [2017-04-17 23:52:27] [DEBUG] mdns: Avahi Browser: NEW service 'f8e903c40ad9@AudioCast_Comedor' type '_raop._tcp' proto 0 [2017-04-17 23:52:27] [DEBUG] mdns: Avahi Resolver: resolved service 'f8e903c40ad9@AudioCast_Comedor' type '_raop._tcp' proto 0, host dlinkap-4.local [2017-04-17 23:52:27] [DEBUG] mdns: Avahi Browser: NEW service 'f8e903c40ad9@AudioCast_Comedor' type '_raop._tcp' proto 1 [2017-04-17 23:52:27] [DEBUG] mdns: Avahi Record Browser (dlinkap-4.local, proto 0): NEW record 192.168.0.50 for service type '_raop._tcp' [2017-04-17 23:52:27] [DEBUG] raop: Event for AirPlay device AudioCast_Comedor (port 5002, id f8e903c40ad9) [2017-04-17 23:52:27] [ INFO] raop: Adding AirPlay device f8e903c40ad9@AudioCast_Comedor: password: 0, encrypt: 1, metadata: 0, type AirPort Express 1 - 802.11g, address 192.168.0.50:5002 [2017-04-17 23:52:27] [DEBUG] db: Running query 'SELECT s.selected, s.volume FROM speakers s WHERE s.id = 273679674247897;' [2017-04-17 23:52:27] [DEBUG] mdns: Avahi Resolver: resolved service 'f8e903c40ad9@AudioCast_Comedor' type '_raop._tcp' proto 1, host dlinkap-4.local [2017-04-17 23:52:27] [ WARN] mdns: Ignoring announcement from dlinkap-4.local, address fe80::fae9:3ff:fec4:ad9 is link-local [2017-04-17 23:52:27] [DEBUG] mdns: Avahi Record Browser (dlinkap-4.local, proto 1): no more results (CACHE_EXHAUSTED) [2017-04-17 23:52:48] [DEBUG] dacp: DACP request: /ctrl-int/1/getproperty?properties=dmcp.volume&session-id=2014111866 [2017-04-17 23:52:48] [DEBUG] player: Player status: stopped [2017-04-17 23:52:48] [DEBUG] dacp: DACP request: /ctrl-int/1/getspeakers?session-id=2014111866 [2017-04-17 23:52:50] [DEBUG] dacp: DACP request: /ctrl-int/1/setspeakers?speaker-id=0x48EE0C649791,0xF8E903C40AD9,0x48EE0C648D69,0x48EE0C648DE1&session-id=2014111866 [2017-04-17 23:52:50] [DEBUG] dacp: Speaker id converted with ret 0, param 0x48EE0C649791,0xF8E903C40AD9,0x48EE0C648D69,0x48EE0C648DE1, dec val 80187247335313. [2017-04-17 23:52:50] [DEBUG] dacp: Speaker id converted with ret 0, param 0xF8E903C40AD9,0x48EE0C648D69,0x48EE0C648DE1, dec val 273679674247897. [2017-04-17 23:52:50] [DEBUG] dacp: Speaker id converted with ret 0, param 0x48EE0C648D69,0x48EE0C648DE1, dec val 80187247332713. [2017-04-17 23:52:50] [DEBUG] dacp: Speaker id converted with ret 0, param 0x48EE0C648DE1, dec val 80187247332833. ..... 2017-04-17 23:53:35] [ LOG] raop: No response from 'AudioCast_Comedor' (192.168.0.50) to OPTIONS request [2017-04-17 23:53:35] [DEBUG] player: Callback from AirPlay to device_probe_cb [2017-04-17 23:53:35] [DEBUG] main: Command has 0 pending events [2017-04-17 23:53:35] [ LOG] dacp: Speakers de/activation failed!

Wrong ip? Home lan is 192.168.9.x

ejurgensen commented 7 years ago

Yes, wrong ip. I've seen before that during startup some devices announce unroutable ip's (those link-local addresses that are getting ignored). Haven't seen this kind of ip before, however.

What I suggest to debug:

  1. Unplug a device
  2. Start "avahi-browse -r -k _raop._tcp"
  3. Plug in the device and watch which announcements avahi reports - does the correct ip get announced? If so, at what time?
  4. When the correct ip is announced, avahi should tell forked-daapd - so please check the logs of forked-daapd if anything happens at that time.
otrojaramago commented 7 years ago

After reentering the command:

= wlp2s0 IPv4 f8e903c40ad9@AudioCast_Comedor _raop._tcp local hostname = [dlinkap-2.local] address = [192.168.9.154] port = [5002] txt = ["txtvers=1" "vn=3" "pw=false" "sr=44100" "ss=16" "ch=2" "cn=0,1" "et=0,1" "ek=1" "sv=false" "sm=false" "tp=UDP"]

Seems problems with avahi. Setting adapters with static ip solves the problem

ejurgensen commented 7 years ago

I had another look at this, and I think it is a bug in forked-daapd. The device is changing its address, but at that point forked-daapd has stopped the resolver for the service, so doesn't get a notification about the change. It seems keeping the resolver alive will solve it, but I will need to test it some more.

otrojaramago commented 7 years ago

Nice to see your progress!

ejurgensen commented 7 years ago

Fixing this issue opened a can of other bugs that also needed to be squashed, so it was good you brought my attention to it. These fixes are now merged into master, hope they do their job.

I actually got hold of a D-link and did some testing with it. With the modifications it works most of the time, but there was still once or twice where the notification about IP change was not given by the Avahi resolver to forked-daapd. This was hard to reproduce, so also hard to debug. Thus, I won't be able to get that last part completely fixed.