owntone-server
owntone-server copied to clipboard
owntone
AirPlay to Homepods no longer working
Hey there,
at first thanks for your amazing work with owntone. I absolutely love it and use it all the time.
Since a few days i have the following problem and im not able to solve it.
I have multiple AirPlay Speakers around the house (e.g. SONOS) which are working fine. I also got 2 HomePod Minis which stopped working.
When I try to connect to one of them. (via API Call or directly from Owntone does not matter) i always get the following message in the logs:
[2021-11-16 19:09:04] [ LOG] airplay: No response to SETUP (session) from 'Küche' [2021-11-16 19:09:04] [ LOG] player: The AirPlay 2 device 'Küche' failed to activate [2021-11-16 19:09:04] [ LOG] web: JSON api request failed with error code 500 (/api/outputs/246477815158987)
I hope somebody can help me. Of coure Password protection is off and AirPlay access is set to everyone. Its been working fine before.
I already tried turning off/on raop and off/on Ipv6
Thanks!
Thanks for the nice words about OwnTone. I can only make a guess, but perhaps it is because the encryption keys that are exchanged during initial pairing are invalid. The SETUP request is the first encrypted request from OwnTone, and if the Homepod can't decrypt it then it is possible that it just doesn't respond.
Whether there is an immediate cure for this depends on the type of pairing. Can you share a debug level log? Please only share the part where you can see OwnTone starts taking to the HomePod (check for the airplay label).
Are you able to confirm which version of HomePod OS you are running too please?
[2021-11-16 20:44:37] [DEBUG] web: JSON api request: '/api/outputs/246477815158987' [2021-11-16 20:44:37] [DEBUG] player: Speaker enable: 'Küche' (id=246477815158987) [2021-11-16 20:44:37] [DEBUG] player: Registered callback to device_activate_cb with id 0 (device 0x741cf0, Küche) [2021-11-16 20:44:37] [DEBUG] player: Number of active callbacks: 1 [2021-11-16 20:44:37] [DEBUG] player: Subscription request for quality 44100/16/2 (now 1 subscribers) [2021-11-16 20:44:37] [DEBUG] raop: device_start: Sending OPTIONS to 'Küche' [2021-11-16 20:44:37] [DEBUG] player: Callback request received, id is 0 [2021-11-16 20:44:37] [DEBUG] player: Unsubscription request for quality 44100/16/2 (now 0 subscribers) [2021-11-16 20:44:37] [DEBUG] player: Making deferred callback to device_activate_cb, id was 0 [2021-11-16 20:44:37] [DEBUG] player: Callback from AirPlay 1 device Küche to device_activate_cb (status 1)
This is the log I was able to find, when trying to connect to the HomePod. No Airplay label appears. There would only be much more with the "player" label
I´m using HomePod OS 15.1.1 Thanks a lot for your help!
That was a unexpected log, here it seems to be Airplay 1. When the log says "raop:" it is Airplay 1, "airplay:" is Airplay 2. There is also no error. OwnTone (currently) prefers Airplay 1 if the speaker announces support for both. Perhaps you had "raop_disable" set to true in the config for the first error you reported? In that case please set it again and try to get the Airplay 2 logging.
@aleszczynskig are your Homepods also version 15.1.1? If so, are they also failing with no response on SETUP?
I'm on 15.1. Scared to update in case they break, that would not be an acceptable situation for me to be in.
I think I found the right section in the logs:
[2021-11-17 16:47:13] [DEBUG] web: JSON api request: '/api/outputs/246477814693728' [2021-11-17 16:47:13] [DEBUG] player: Speaker enable: 'Schlafzimmer' (id=246477814693728) [2021-11-17 16:47:13] [DEBUG] player: Registered callback to device_activate_cb with id 2 (device 0x9dd308, Schlafzimmer) [2021-11-17 16:47:13] [DEBUG] player: Number of active callbacks: 3 [2021-11-17 16:47:13] [DEBUG] raop: device_start: Sending OPTIONS to 'Schlafzimmer' [2021-11-17 16:47:13] [DEBUG] raop: startup_options: Sending ANNOUNCE to 'Schlafzimmer' [2021-11-17 16:47:13] [DEBUG] raop: Local address: 192.168.1.26 (LL: no) port 37716 [2021-11-17 16:47:13] [ INFO] raop: Setting up AirPlay session 247634330 (192.168.1.26 -> 192.168.1.37) [2021-11-17 16:47:13] [DEBUG] raop: startup_announce: Sending SETUP to 'Schlafzimmer' [2021-11-17 16:47:15] [DEBUG] mdns: Avahi Resolver: resolved service 'Schlafzimmer' type '_airplay._tcp' proto 0, host Schlafzimmer.local, address 192.168.1.37 [2021-11-17 16:47:15] [DEBUG] mdns: Connection test to 192.168.1.37:7000 completed successfully [2021-11-17 16:47:15] [DEBUG] airplay: Event for AirPlay device 'Schlafzimmer' (port 7000, id e02b9696ff60) [2021-11-17 16:47:15] [ INFO] airplay: Adding AirPlay device 'Schlafzimmer': features 0x4A7FCA00,0xBC356BD0, type HomePod, address 192.168.1.37:7000 [2021-11-17 16:47:15] [DEBUG] mdns: Avahi Resolver: resolved service 'Schlafzimmer' type '_airplay._tcp' proto 0, host Schlafzimmer.local, address 192.168.1.37 [2021-11-17 16:47:15] [DEBUG] mdns: Connection test to 192.168.1.37:7000 completed successfully [2021-11-17 16:47:15] [DEBUG] airplay: Event for AirPlay device 'Schlafzimmer' (port 7000, id e02b9696ff60) [2021-11-17 16:47:15] [ INFO] airplay: Adding AirPlay device 'Schlafzimmer': features 0x4A7FCA00,0xBC356BD0, type HomePod, address 192.168.1.37:7000 [2021-11-17 16:47:15] [DEBUG] mdns: Avahi Resolver: resolved service 'E02B9696FF60@Schlafzimmer' type '_raop._tcp' proto 0, host Schlafzimmer.local, address 192.168.1.37 [2021-11-17 16:47:16] [DEBUG] mdns: Connection test to 192.168.1.37:7000 completed successfully [2021-11-17 16:47:16] [DEBUG] raop: Event for AirPlay device 'Schlafzimmer' (port 7000, id e02b9696ff60) [2021-11-17 16:47:16] [ INFO] raop: Adding AirPlay device 'Schlafzimmer': password: 0, verification: 0, encrypt: 0, authsetup: 0, metadata: 7, type HomePod, address 192.168.1.37:7000 [2021-11-17 16:47:16] [DEBUG] mdns: Avahi Resolver: resolved service 'E02B9696FF60@Schlafzimmer' type '_raop._tcp' proto 0, host Schlafzimmer.local, address 192.168.1.37 [2021-11-17 16:47:16] [DEBUG] mdns: Connection test to 192.168.1.37:7000 completed successfully [2021-11-17 16:47:16] [DEBUG] raop: Event for AirPlay device 'Schlafzimmer' (port 7000, id e02b9696ff60) [2021-11-17 16:47:16] [ INFO] raop: Adding AirPlay device 'Schlafzimmer': password: 0, verification: 0, encrypt: 0, authsetup: 0, metadata: 7, type HomePod, address 192.168.1.37:7000
Hope that does help now.
This is still raop, so Airplay 1, and the original error is not present. You need to reproduce the original error and get the full logging of that.
I'm sorry I'm not that familiar with logs :) But I think I did found the right section now..
Thanks for your help!
Thanks, that log is exactly right. The log shows that the initial pairing/key exchange is going as expected, and that the HomePod is not replying to the SETUP request. It might be due to keys, in which case we are in trouble, but there is also another possibility. In the SETUP request the local address is also communicated, and I see it is set to an ipv6 address. Perhaps that is just not going down well with the HomePod. Could you retry with ipv6 set to disabled and then post the similar log?
I dont know exactly what I did but they do work again. I turned on/off Ipv6 multiple times before and it changed nothing but all of a sudden at first one HomePod worked again and now they do both work. I will keep an eye on this because im not quite sure what did the trick there. I also renamed them both and gave them a new static IP. I think we can close this for now, but thank you again for your efforts!
Unfortunately this lasted only a few days.. The problem is back. At first with only one HomePod but now both of them don't work again.
I even reset them both in the Home App, but It didn't help.
Here´s the log with Ipv6 disabled, and raop set to disabled:
[2021-11-23 19:11:07] [DEBUG] airplay: device_start: Sending GET /info to 'Schlafzimmer' [2021-11-23 19:11:07] [DEBUG] airplay: Local address: 192.168.1.26 (LL: no) port 59680 [2021-11-23 19:11:07] [DEBUG] airplay: Status flags from 'Schlafzimmer' was 99332: cable attached 1, one time pairing 0, password 0, PIN 0 [2021-11-23 19:11:07] [DEBUG] airplay: device_start: Sending pair setup 1 to 'Schlafzimmer' [2021-11-23 19:11:07] [DEBUG] airplay: device_start: Sending pair setup 2 to 'Schlafzimmer' [2021-11-23 19:11:07] [ WARN] player: Output delay detected: player is 24 ticks behind, catching up [2021-11-23 19:11:07] [DEBUG] airplay: Ciphering setup of 'Schlafzimmer' completed succesfully, now using encrypted mode [2021-11-23 19:11:07] [DEBUG] airplay: pair_success: Sending SETUP (session) to 'Schlafzimmer' [2021-11-23 19:11:10] [DEBUG] mdns: Avahi Resolver: resolved service 'Schlafzimmer' type '_airplay._tcp' proto 0, host Schlafzimmer.local, address 192.168.1.37 [2021-11-23 19:11:11] [DEBUG] mdns: Connection test to 192.168.1.37:7000 completed successfully [2021-11-23 19:11:11] [DEBUG] airplay: Event for AirPlay device 'Schlafzimmer' (port 7000, id e02b9696ff60) [2021-11-23 19:11:11] [ INFO] airplay: Adding AirPlay device 'Schlafzimmer': features 0x4A7FCA00,0xBC354BD0, type HomePod, address 192.168.1.37:7000 [2021-11-23 19:11:11] [DEBUG] mdns: Avahi Resolver: resolved service 'E02B9696FF60@Schlafzimmer' type '_raop._tcp' proto 0, host Schlafzimmer.local, address 192.168.1.37 [2021-11-23 19:11:11] [DEBUG] mdns: Connection test to 192.168.1.37:7000 completed successfully [2021-11-23 19:11:11] [DEBUG] raop: Event for AirPlay device 'Schlafzimmer' (port 7000, id e02b9696ff60) [2021-11-23 19:11:11] [ INFO] raop: Disabling AirPlay 1 (RAOP) for device 'Schlafzimmer' as set in config [2021-11-23 19:11:22] [ WARN] event: evrtsp_read: read timeout: Success [2021-11-23 19:11:22] [ LOG] airplay: No response to SETUP (session) from 'Schlafzimmer' [2021-11-23 19:11:22] [DEBUG] player: Callback request received, id is 1 [2021-11-23 19:11:22] [DEBUG] player: Unsubscription request for quality 44100/16/2 (now 1 subscribers) [2021-11-23 19:11:22] [DEBUG] player: Making deferred callback to device_activate_cb, id was 1 [2021-11-23 19:11:22] [DEBUG] player: Callback from AirPlay 2 device Schlafzimmer to device_activate_cb (status -1) [2021-11-23 19:11:22] [ LOG] player: The AirPlay 2 device 'Schlafzimmer' failed to activate [2021-11-23 19:11:22] [DEBUG] main: Command has 0 pending events [2021-11-23 19:11:22] [DEBUG] player: Status update - status: 4, events: 12, caller: speaker_generic_bh [2021-11-23 19:11:22] [DEBUG] mpd: Asynchronous listener callback called with event type 12. [2021-11-23 19:11:22] [DEBUG] player: 0. Active callback: device_streaming_cb [2021-11-23 19:11:22] [DEBUG] mpd: Notify clients waiting for idle results: 12 [2021-11-23 19:11:22] [ LOG] web: JSON api request failed with error code 500 (/api/outputs/246477814693728)
Sorry to hear about that. Of course very strange that it comes and goes, but with both at the same time. I suppose there might be some clue in that. Sadly the log doesn't provide any clues as to what could be done to fix it.
If anyone else observes the same behavior I hope they will add a note here. We be interesting to know how much of a general issue this is.
My homepods have stopped working also but I don't have the same errors in the logs but I have the following:
[2022-01-02 20:17:41] [ LOG] mdns: Avahi Resolver failure: service 'Living Room (2)' type '_airplay._tcp' proto 0: Timeout reached
[2022-01-02 20:17:41] [ LOG] mdns: Avahi Resolver failure: service 'Living Room (2)' type '_airplay._tcp' proto 0: Timeout reached
[2022-01-02 20:17:41] [ LOG] mdns: Avahi Resolver failure: service 'E02B96ACF27A@Living Room (2)' type '_raop._tcp' proto 0: Timeout reached
...
[2022-01-02 20:17:41] [ LOG] mdns: Avahi Resolver failure: service '58D349154F40@Downstairs Guest Bedroom' type '_raop._tcp' proto 0: Timeout reached
[2022-01-03T01:17:47Z WARN libmdns::fsm] couldn't parse packet from 192.168.10.1:5353: type 47 is invalid
[2022-01-03T01:17:48Z WARN libmdns::fsm] couldn't parse packet from 192.168.10.1:5353: type 47 is invalid
[2022-01-03T01:17:50Z WARN libmdns::fsm] couldn't parse packet from 192.168.10.1:5353: type 47 is invalid
[2022-01-03T01:17:54Z WARN libmdns::fsm] couldn't parse packet from 192.168.10.1:5353: type 47 is invalid
@uchagani yes this looks different. Looks like an mdns issue, perhaps you are running via Docker? Either way, I can't really help with it.
I have the same issue, I can stream to other devices but not to a HomePod
web: JSON api request: '/api/outputs/233797575838827/toggle' Feb 16 13:15:49 raspberrypi owntone[16731]: [2022-02-16 13:15:49] [DEBUG] player: Speaker enable: 'Living Room' (id=233797575838827) Feb 16 13:15:49 raspberrypi owntone[16731]: [2022-02-16 13:15:49] [DEBUG] player: Registered callback to device_activate_cb with id 0 (device 0x10630d8, Living Room) Feb 16 13:15:49 raspberrypi owntone[16731]: [2022-02-16 13:15:49] [DEBUG] player: Number of active callbacks: 1 Feb 16 13:15:49 raspberrypi owntone[16731]: [2022-02-16 13:15:49] [DEBUG] player: Subscription request for quality 44100/16/2 (now 1 subscribers) Feb 16 13:15:49 raspberrypi owntone[16731]: [2022-02-16 13:15:49] [DEBUG] raop: device_start: Sending OPTIONS to 'Living Room' Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] player: Callback request received, id is 0 Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] player: Unsubscription request for quality 44100/16/2 (now 0 subscribers) Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] player: Making deferred callback to device_activate_cb, id was 0 Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] player: Callback from AirPlay 1 device Living Room to device_activate_cb (status 1) Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] main: Command has 0 pending events Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] player: Status update - status: 2, events: 12, caller: speaker_generic_bh Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] mpd: Asynchronous listener callback called with event type 12. Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] mpd: Notify clients waiting for idle results: 12 Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] web: notify callback reason: 11 Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] web: notify callback reply: 4 Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] web: JSON api request: '/api/player' Feb 16 13:15:50 raspberrypi owntone[16731]: [2022-02-16 13:15:50] [DEBUG] player: Player status: stopped
edit
Disabling ipv6 did the trick for me
