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.09k stars 234 forks source link

Apple TV Version 4 (A1625) stops streaming randomly #855

Closed NorbertRoller closed 4 years ago

NorbertRoller commented 4 years ago

It did work until several weeks ago, but after Apple has updated the Firmware (to 13.2) it is unreliable. Several other Airport express work flawless. All units are hooked up to the Ethernet cable.

The streamer is a raspberry and I use apple remote tool to select music and speakers.

[ LOG] player: Output device with id 102859367229 has disappeared from our
[ LOG] raop: Device 'Apple TV Wozi' closed RTSP connection [ LOG] player: The AirPlay device 'Apple TV Wozi' FAILED

It will play music for a while, when selecting it again

forked-daapd was update today, again.

ejurgensen commented 4 years ago

Ok doesn't sound good. I will see if I can reproduce with my ATV4. How long does it play? Is there any system to how long it takes before disconnecting?

NorbertRoller commented 4 years ago

Completely random. Anything from 10 seconds to 1 hour

While browsing the open issues, I have seen a similar report.

Any thing I can do to help?

Liebe Grüße Norbert Roller

Am 09.12.2019 um 10:45 schrieb ejurgensen notifications@github.com:

 Ok doesn't sound good. I will see if I can reproduce with my ATV4. How long does it play? Is there any system to how long it takes before disconnecting?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or unsubscribe.

ejurgensen commented 4 years ago

I have now tried with my ATV4, which is also A1625 with tvOS 13.2. I didn't see any unexpected disconnections. It played for about an hour.

I did notice that ATV's support for this kind of streaming seems to be waning. Previously, it would display artwork and playback progress, but now it didn't show anything. Also, I had to extend the ATV's sleep timer in the settings, otherwise it would in fact disconnect and go to sleep during playback. I expect it is not the sleep timer that is causing your issues?

I am not sure what you or I can do from here. Maybe I just got lucky that it didn't disconnect, but even if it does disconnect next time, it seems to be rare enough that it will be impossible to debug.

NorbertRoller commented 4 years ago

Thanks for trying.

The sleep is set to 5h. Since a message is coming into the log, we should be able to find the origin modul or subroutine that triggers the message.

If you point me into the right direction I can do some more search. I am able to read and write code, but have not build the tool chain to compile the program.

Liebe Grüße Norbert Roller

Am 10.12.2019 um 08:50 schrieb ejurgensen notifications@github.com:

 I have now tried with my ATV4, which is also A1625 with tvOS 13.2. I didn't see any unexpected disconnections. It played for about an hour.

I did notice that ATV's support for this kind of streaming seems to be waning. Previously, it would display artwork and playback progress, but now it didn't show anything. Also, I had to extend the ATV's sleep timer in the settings, otherwise it would in fact disconnect and go to sleep during playback. I expect it is not the sleep timer that is causing your issues?

I am not sure what you or I can do from here. Maybe I just got lucky that it didn't disconnect, but even if it does disconnect next time, it seems to be rare enough that it will be impossible to debug.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or unsubscribe.

ejurgensen commented 4 years ago

You are welcome to look more into it. If you change the log level to debug you should be able to trace the sequence of events. It is probably something like this:

A. Avahi tells us that the device is gone. This happens in mdns_avahi.c browse_callback(), line 802. The callback is made to raop_device_cb() in raop.c. This again calls player_device_remove(), which however does not remove the device if there is a playback session. B. Something triggers the connection failed callback raop_rtsp_close_cb() in raop.c. I don't know what exactly that is. Perhaps it just that the device is disconnecting.

ejurgensen commented 4 years ago

You could also experiment with setting ipv6 to disabled and setting the "permanent" setting to true for the device. Just to see if it makes a difference.

NorbertRoller commented 4 years ago

Ipv6 was set to “no“ I have changed it to disable Permanent was false and I changed it to true

During the weekend I will do some more testing.

Many thanks for your advice

NorbertRoller commented 4 years ago

It took me a little while to find out why the program didn't start, anymore. I removed it from the PI and installed again. I rebuild the .cfg and add the lines you recommended. But it didn't help. The programm stopped with an error. After starting with sudo /usr/sbin/forked-daapd -f

I got the following message [ LOG] config: [root:272] no such option 'permanent' [FATAL] config: Parse error in config file /etc/forked-daapd.conf [FATAL] main: Config file errors; please fix your config

I had to comment the "permanent" line to solve the issue. Just changing the parameter from true to false didn't fix it.

Any idea ?

I guess I have to remount the ATV 4 and can only do this during the weekend, when I am back from the business trip.

At least I have a fresh installation now :-)

ejurgensen commented 4 years ago

If you take an extra look at the config file you will probably find the cause yourself: "permanent" is not a global option, you must set it for the particular device. So in your case you should have:

airplay "Apple TV Wozi" {
  permanent = true
}
NorbertRoller commented 4 years ago

While searching the internet, I found another solution that might help. It sits within the AVAHI deamon. In the config, the IPV6 can be disabled. (reboot is necessary)

sudo nano /etc/avahi/avahi-daemon.conf

line use-ipv6=yes change to use-ipv6=no

To check the ports are disable, one can try: sudo netstat -tulpen | grep avahi

Lets see how it goes and if this doesn't help I will try above

NorbertRoller commented 4 years ago

I made the change in the avahi-daemon.conf as well as all the changes you recommended in the forked-daapd.conf Unfortunately I had no luck. The ATV4 stops streaming randomly. I have a spare PI and will do complete new setup. Let's see how this goes.

ejurgensen commented 4 years ago

What does the log say now when playback stops?

NorbertRoller commented 4 years ago

Hi, happy new year at first. I have used the quiet time to setup a raspberry from scratch. Just in case some old left overs cause the issue. Unfortunately this didn't help. ATV4 fails randomly.

Below is the error messages since 8:30 [2020-01-02 08:33:05] [ LOG] raop: Send error for 'Apple TV Wozi': Connection refused [2020-01-02 08:51:36] [ LOG] raop: Send error for 'Apple TV Wozi': Connection refused [2020-01-02 09:07:04] [ LOG] raop: Send error for 'Apple TV Wozi': Connection refused

One more information, that might help: The ATV4 streams nicely for a full day if an Ipad streams Apple Music. So a defect of the ATV4 is unlikely.

NorbertRoller commented 4 years ago

I did some more investigation. I switched log to "debug" and waited for ATV4 to stop Below is the log I extracted:

**Still working**
[2020-01-02 10:29:18] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Apple TV Wozi'
[2020-01-02 10:29:18] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Schlafzimmer AE2'
[2020-01-02 10:29:18] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Küche AE2'
[2020-01-02 10:29:18] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Ilka AE2'
[2020-01-02 10:29:18] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Gaeste gross AE2'
[2020-01-02 10:29:18] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Buero AE2'
[2020-01-02 10:29:18] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Bad oben'
[2020-01-02 10:29:26] [DEBUG]     dacp: DACP request: '/ctrl-int/1/setproperty?dmcp.device-prevent-playback=1'
...
[2020-01-02 10:29:36] [DEBUG]     raop: Metadata sr=44100, pos_ms=878023, len_ms=0, start=3309474812, display=3309444092, pos=3348195626, end=3309474812, rtptime=334
[2020-01-02 10:29:36] [DEBUG]     raop: send_metadata: Sending SET_PARAMETER to 'Bad oben'
[2020-01-02 10:29:36] [DEBUG]     raop: send_artwork: Sending SET_PARAMETER to 'Bad oben'
[2020-01-02 10:29:36] [DEBUG]     raop: send_progress: Sending SET_PARAMETER to 'Bad oben'
[2020-01-02 10:29:36] [ WARN]     raop: SET_PARAMETER metadata/artwork/progress request to 'Schlafzimmer AE2' failed (proceeding anyway): 456 Header Field Not Valid
[2020-01-02 10:29:36] [ WARN]     raop: SET_PARAMETER metadata/artwork/progress request to 'Ilka AE2' failed (proceeding anyway): 456 Header Field Not Valid
[2020-01-02 10:29:36] [ WARN]     raop: SET_PARAMETER metadata/artwork/progress request to 'Buero AE2' failed (proceeding anyway): 456 Header Field Not Valid
[2020-01-02 10:29:36] [ WARN]     raop: SET_PARAMETER metadata/artwork/progress request to 'Gaeste gross AE2' failed (proceeding anyway): 456 Header Field Not Valid
[2020-01-02 10:29:36] [ WARN]     raop: SET_PARAMETER metadata/artwork/progress request to 'Küche AE2' failed (proceeding anyway): 456 Header Field Not Valid
[2020-01-02 10:29:36] [ WARN]     raop: SET_PARAMETER metadata/artwork/progress request to 'Schlafzimmer AE2' failed (proceeding anyway): 456 Header Field Not Valid
[2020-01-02 10:29:36] [ WARN]     raop: SET_PARAMETER metadata/artwork/progress request to 'Ilka AE2' failed (proceeding anyway): 456 Header Field Not Valid
[2020-01-02 10:29:36] [ WARN]     raop: SET_PARAMETER metadata/artwork/progress request to 'Buero AE2' failed (proceeding anyway): 456 Header Field Not Valid
[2020-01-02 10:29:36] [ WARN]     raop: SET_PARAMETER metadata/artwork/progress request to 'Gaeste gross AE2' failed (proceeding anyway): 456 Header Field Not Valid
[2020-01-02 10:29:36] [ WARN]     raop: SET_PARAMETER metadata/artwork/progress request to 'Küche AE2' failed (proceeding anyway): 456 Header Field Not Valid
[2020-01-02 10:29:38] [DEBUG]     dacp: DACP request: '/ctrl-int/1/setproperty?dmcp.device-prevent-playback=0'
**ATV4 not working, all others are working**
[2020-01-02 10:29:48] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Apple TV Wozi'
[2020-01-02 10:29:48] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Schlafzimmer AE2'
[2020-01-02 10:29:48] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Küche AE2'
[2020-01-02 10:29:48] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Ilka AE2'
[2020-01-02 10:29:48] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Gaeste gross AE2'
[2020-01-02 10:29:48] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Buero AE2'
[2020-01-02 10:29:48] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Bad oben'

**de-selecting and selecting the ATV4 in the remote tool switches the ATV4 back on**
NorbertRoller commented 4 years ago

I had the issue happening a few more times and it always is the same log as the one above.

I checked the CPU usage and only 11% are used.

NorbertRoller commented 4 years ago

Now it showed a new pattern: [2020-01-02 11:46:21] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Apple TV Wozi' [2020-01-02 11:46:21] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Schlafzimmer AE2' [2020-01-02 11:46:21] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Küche AE2' [2020-01-02 11:46:21] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Ilka AE2' [2020-01-02 11:46:21] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Gaeste gross AE2' [2020-01-02 11:46:21] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Buero AE2' [2020-01-02 11:46:21] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Bad oben' [2020-01-02 11:46:36] [DEBUG] dacp: DACP request: '/ctrl-int/1/setproperty?dmcp.device-prevent-playback=1' [2020-01-02 11:46:38] [DEBUG] daap: Update request: client closed connection [2020-01-02 11:46:49] [DEBUG] dacp: DACP request: '/ctrl-int/1/setproperty?dmcp.device-prevent-playback=0' [2020-01-02 11:46:51] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Apple TV Wozi' [2020-01-02 11:46:51] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Schlafzimmer AE2' [2020-01-02 11:46:51] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Küche AE2' [2020-01-02 11:46:51] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Ilka AE2' [2020-01-02 11:46:51] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Gaeste gross AE2' [2020-01-02 11:46:51] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Buero AE2' [2020-01-02 11:46:51] [DEBUG] raop: keep_alive: Sending OPTIONS to 'Bad oben'

ejurgensen commented 4 years ago

Yes, I think you have found a good clue there. "device-prevent-playback" is not supported, so forked-daapd just replies with an "ok" to it. Perhaps that is not good enough for the Apple TV.

Other than what the name implies I don't know what device-prevent-playback is supposed to do: How is it different than pause/stop? Why is the device making the request? Google searching gives this https://github.com/philippe44/LMS-to-Raop/blame/master/application/squeeze2raop/squeeze2raop.c, which I will look more into. Maybe that will show what it's about.

ejurgensen commented 4 years ago

I have made an experimental modification to forked-daapd so that it will now react to device-prevent-playback by enabling/disabling the speaker. However, I can't test myself if it helps, because for some reason my ATV4 doesn't have the issue, and never makes those requests.

So I hope you are able to test for me. The modification is in this branch: https://github.com/ejurgensen/forked-daapd/tree/apple_updates2. Let me know if you would like me to make a RPi deb with the modification for you.

NorbertRoller commented 4 years ago

Yes please. I am at the location until Sunday night and can do testing. After that i am gone for a full week.

Linux 4.19.75-v7+

ejurgensen commented 4 years ago

Here is for both Raspbian Stretch and Buster: Stretch: http://gyfgafguf.dk/temp/forked-daapd_27.0.101~test1-2_armhf.deb Buster: http://gyfgafguf.dk/temp/forked-daapd_27.0.101~test1-3_armhf.deb

NorbertRoller commented 4 years ago

The Pi is setup with Buster and the forked-daapd_27.0.101~test1-2_armhf.deb is installed. Everything is up an running. Streaming is going on. Let's wait and see. I will get back to you as soon as I have a result. Thanks for your quick response and support.

NorbertRoller commented 4 years ago

Bad news. It took only a short time and it stopped again: This is the part of the log that might help:

[2020-01-03 13:45:05] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Apple TV Wozi'
[2020-01-03 13:45:05] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Schlafzimmer AE2'
[2020-01-03 13:45:05] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Küche AE2'
[2020-01-03 13:45:05] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Ilka AE2'
[2020-01-03 13:45:05] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Gaeste gross AE2'
[2020-01-03 13:45:05] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Buero AE2'
[2020-01-03 13:45:05] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Bad oben'
**[2020-01-03 13:45:05] [  LOG]     raop: Keep alive request to 'Apple TV Wozi' failed: 0 (null)**
**[2020-01-03 13:45:05] [  LOG]     raop: Device 'Apple TV Wozi' closed RTSP connection**
**[2020-01-03 13:45:05] [DEBUG]     raop: Cleaning up failed session (deferred) on device 'Apple TV Wozi'**
[2020-01-03 13:45:05] [DEBUG]   player: Callback request received, id is 6
[2020-01-03 13:45:05] [DEBUG]   player: Making deferred callback to device_streaming_cb, id was 6
[2020-01-03 13:45:05] [DEBUG]   player: Callback from AirPlay to device_streaming_cb (status -1)
[2020-01-03 13:45:05] [  LOG]   player: The AirPlay device 'Apple TV Wozi' FAILED
[2020-01-03 13:45:05] [DEBUG]   player: 0. Active callback: device_streaming_cb
[2020-01-03 13:45:05] [DEBUG]   player: 1. Active callback: device_streaming_cb
[2020-01-03 13:45:05] [DEBUG]   player: 2. Active callback: device_streaming_cb
[2020-01-03 13:45:05] [DEBUG]   player: 3. Active callback: device_streaming_cb
[2020-01-03 13:45:05] [DEBUG]   player: 4. Active callback: device_streaming_cb
[2020-01-03 13:45:05] [DEBUG]   player: 5. Active callback: device_streaming_cb
[2020-01-03 13:45:07] [DEBUG]     mdns: Avahi Resolver: resolved service 'C869CD745555@Apple TV Wozi' type '_raop._tcp' proto 0, host Apple-TV-Wozi.local, address 192.168.0.99
[2020-01-03 13:45:07] [DEBUG]     mdns: Connection test to 192.168.0.99:7000 completed successfully
[2020-01-03 13:45:07] [DEBUG]     raop: Event for AirPlay device 'Apple TV Wozi' (port 7000, id c869cd745555)
[2020-01-03 13:45:07] [ INFO]     raop: Adding AirPlay device 'Apple TV Wozi': password: 0, verification: 1, encrypt: 0, authsetup: 0, metadata: 1, type AppleTV4, address 192.168.0.99:7000
NorbertRoller commented 4 years ago

once more but a shorter log

[2020-01-03 14:22:35] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Apple TV Wozi'
[2020-01-03 14:22:35] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Schlafzimmer AE2'
[2020-01-03 14:22:35] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Küche AE2'
[2020-01-03 14:22:35] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Ilka AE2'
[2020-01-03 14:22:35] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Gaeste gross AE2'
[2020-01-03 14:22:35] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Buero AE2'
[2020-01-03 14:22:35] [DEBUG]     raop: keep_alive: Sending OPTIONS to 'Bad oben'
**[2020-01-03 14:22:35] [  LOG]     raop: Keep alive request to 'Apple TV Wozi' failed: 0 (null)
[2020-01-03 14:22:35] [  LOG]     raop: Device 'Apple TV Wozi' closed RTSP connection
[2020-01-03 14:22:35] [DEBUG]     raop: Cleaning up failed session (deferred) on device 'Apple TV Wozi'
[2020-01-03 14:22:35] [DEBUG]   player: Callback request received, id is 6
[2020-01-03 14:22:35] [DEBUG]   player: Making deferred callback to device_streaming_cb, id was 6
[2020-01-03 14:22:35] [DEBUG]   player: Callback from AirPlay to device_streaming_cb (status -1)
[2020-01-03 14:22:35] [  LOG]   player: The AirPlay device 'Apple TV Wozi' FAILED
[2020-01-03 14:22:35] [DEBUG]   player: 0. Active callback: device_streaming_cb
[2020-01-03 14:22:35] [DEBUG]   player: 1. Active callback: device_streaming_cb
[2020-01-03 14:22:35] [DEBUG]   player: 2. Active callback: device_streaming_cb
[2020-01-03 14:22:35] [DEBUG]   player: 3. Active callback: device_streaming_cb
[2020-01-03 14:22:35] [DEBUG]   player: 4. Active callback: device_streaming_cb
[2020-01-03 14:22:35] [DEBUG]   player: 5. Active callback: device_streaming_cb
[2020-01-03 14:22:38] [DEBUG]     mdns: Avahi Resolver: resolved service 'C869CD745555@Apple TV Wozi' type '_raop._tcp' proto 0, host Apple-TV-Wozi.local, address 192.168.0.99
[2020-01-03 14:22:38] [DEBUG]     mdns: Connection test to 192.168.0.99:7000 completed successfully
[2020-01-03 14:22:38] [DEBUG]     raop: Event for AirPlay device 'Apple TV Wozi' (port 7000, id c869cd745555)
[2020-01-03 14:22:38] [ INFO]     raop: Adding AirPlay device 'Apple TV Wozi': password: 0, verification: 1, encrypt: 0, authsetup: 0, metadata: 1, type AppleTV4, address 192.168.0.99:7000
ejurgensen commented 4 years ago

Ok, but these are different errors. There is no "device-prevent-playback", so my fix of course doesn't do anything here. The log doesn't really provide clues on these errors, they look exactly like normal device disconnects, e.g. from network error.

BTW please avoid pasting lengthy log file snippets. Either redact them or attach them as files.

NorbertRoller commented 4 years ago

I had already tried another flex cable for the ATV4 and it did not fix the issue. Now I have pulled a new CAT7 Cable to the ATV4. At first it worked, but after 4-5 hours, it dropped out twice. PS: It was unlikely a cable issue as it worked with Apple music for >12h.

ejurgensen commented 4 years ago

I can only speculate about possible causes of this, and that is always a dangerous to do. But a cause that could match the symptoms you describe is if the clocks aren't in sync. When that happens the device may reach a state where it is no longer able to play the audio at the time it thinks it should be played, and then it will probably stop. Usually the clocks stay in sync with forked-daapd acting as ntp server, but maybe that is somehow not working.

Debugging that is complex, and not really possible for me to give clear instructions on. You could, however, try one thing, which is to set this value to 3 and then recompile/retest: https://github.com/ejurgensen/forked-daapd/blob/master/src/outputs.h#L64

If this change has no effect then I would say the above theory is likely incorrect.

raufis27 commented 4 years ago

https://github.com/ejurgensen/forked-daapd/issues/734#issuecomment-573510231

mynameisdaniel32 commented 4 years ago

Also seeing this on both of my HomePods since updating to iOS 13.2 - at different times to each other, sometimes 10 minutes, sometimes 2+ hours of playing they'll drop out. What I did initially notice was that if I tried resuming playback as soon as it dropped out, forked-daapd couldn't actually see the HomePods as available AirPlay devices. Worth noting that my iPhone could still see them both as available AirPlay devices when forked-daapd couldn't. After some time (maybe a minute or two), forked-daapd could see them again.

I then added to my config (for both my HomePods):

airplay "Bedroom HomePod" {
    permanent = true
}

This had no effect on the random drop-outs, but it did allow me to instantly resume playback as soon as they dropped out.

I also updated forked-daapd yesterday (after the change mentioned above) and am still seeing this.

If you have any ideas for testing/debugging, let me know and I can give them a go.

ejurgensen commented 4 years ago

Thanks for the info. Your experience matches what the logs from @raufis27 show: Not only does the HomePod disconnect, it also stops its service announcement. It is almost like it switches off and on again. Perhaps it reaches an error state that makes it restart its service.

It is a very difficult error to debug, and it doesn't help that I can't reproduce. As mentioned above, I think a possible cause of the error is clock sync, so that is where I would start looking. I can give you some pointers to start off with, but when it comes to real work of trial and error you would have to do the heavy lifting.

raufis27 commented 4 years ago

@ejurgensen I can help with troubleshooting. As a dirty workaround I did automate process of reenabling HomePod speaker with NodeRed. Every 5 seconds I am sending {"selected":true} to /api/outputs/ . Not ideal, but works until we figure out the solution.

ejurgensen commented 4 years ago

Sounds great!

So my theory about clock sync is that the speaker reaches a state where it does not have the audio packets that it should play. Let’s say that the device in it is buffer has the packets that it should play from time t1 (oldest packet) to t2 (newest packet), but that the current time is t > t2. Then the device could of course throw away its buffer and wait for the newer packets, but it would also be reasonable to consider this an error and just stop.

This situation could arise from either incorrect timestamps from forked-daapd (t1 and t2 are incorrect), or missing clock sync between forked-daapd and the speaker (t is incorrect).

So to debug you would mainly have to work with src/outputs/raop.c (and possibly src/outputs/rtp_common.c). Some ideas:

  1. Check if the clocks are syncronizing. Whenever the speaker makes a time request, raop_v2_timing_cb() will be called. It should happen at pretty regular intervals. Does that actually happen?
  2. Check if changing the timing and buffer size has any impact: Change OUTPUTS_BUFFER_DURATION to 3 as mentioned above. Maybe also try with 1.
  3. Check if disabling sync altogether has any impact on the issue: Change packets_sync_send() so it doesn’t send anything.
  4. Add logging of the sync packets sent, and look for irregularities – e.g. are the timestamps drifting
  5. And maybe also fiddle with timestamp calculation in packets_sync_send() – does it have an impact?
raufis27 commented 4 years ago

Sorry, how do I do 1. (Check if the clocks are syncronizing) ? I can change the code and recompile, but I am not experienced developer ;)

ejurgensen commented 4 years ago

Let's leave to someone else then. As I mentioned I can provide pointers, but not more than that - it would be too difficult and time-consuming.

mixographer commented 4 years ago

I'll take a shot at some of these suggestions.

NorbertRoller commented 4 years ago

Since the problem is still happening, I have setup a switch with port mirroring and Wireshark to trace it. I have several records and this seems to be the most common lines, before the ATV4 stops playing It looks that a http request is made and aswered with destination not reachable GET /ctrl-int/1/setproperty?dcmp.device-prevent-playback=1 http/1.1 ICMP reports Destination unreachable (Port unreachable)

PS: Since a few weeks I do see the same issues with several Airport Express Version 2 as well.

ejurgensen commented 4 years ago

If the ATV4 makes a such a request it means that it wants playback to stop - I believe this is usually what it will do if it becomes busy, say if you started an app on the ATV4 that needs the audio. So it is strange if it makes such a request out of the blue. It is also strange that forked-daapd's dacp service is reported as unreachable. It is the same port and service that is used for Apple Remote, so is that also not able to connect? Perhaps you can also check forked-daapd's log (set it to debug level) and see how it matches Wireshark.

ejurgensen commented 4 years ago

BTW interesting that it also happens on Airport Express. Those are much cheaper, so I'll see if I can get one of those. Is it the A1392?

NorbertRoller commented 4 years ago

Airport Express = A1392 with latest FW

NorbertRoller commented 4 years ago

If the ATV4 makes a such a request it means that it wants playback to stop - I believe this is usually what it will do if it becomes busy, say if you started an app on the ATV4 that needs the audio. So it is strange if it makes such a request out of the blue. It is also strange that forked-daapd's dacp service is reported as unreachable. It is the same port and service that is used for Apple Remote, so is that also not able to connect? Perhaps you can also check forked-daapd's log (set it to debug level) and see how it matches Wireshark.

It was all OK until September 2019 when the ATV4 was upgraded. When I took the Wireshark, there was no one touching the remote or ATV4. So the request wasn't humanly triggered. I had also set the ATV4 sleep mode for a very long time. It didn't make a difference. I will try debug + Wireshark, tomorrow.

NorbertRoller commented 4 years ago

I have continued to do a lot of reading about this problem as well as tracing with WireShark and the Debug log. So far I have not spotted anything on WireShark that seems to relate to the issue.

However I found this snipped in the LOG-File very close to the time it stopped playing music: [DEBUG] raop: keep_alive: Sending OPTIONS to 'Apple TV Wozi' [ LOG] raop: Device 'Apple TV Wozi' closed RTSP connection [DEBUG] raop: Cleaning up failed session (deferred) on device 'Apple TV Wozi' [DEBUG] player: Callback request received, id is 0 [DEBUG] player: Making deferred callback to device_streaming_cb, id was 0 [DEBUG] player: Callback from AirPlay to device_streaming_cb (status -1) [ LOG] player: The AirPlay device 'Apple TV Wozi' FAILED [DEBUG] player: 1. Active callback: device_streaming_cb [DEBUG] player: 2. Active callback: device_streaming_cb

NorbertRoller commented 4 years ago

Something else I just spotted in Wireshark monitoring the Raspberry / forked-daapd: MDNS Packet send to 224.0.0.251:

I have 5-6 AE2 connected as well and I have never seen a similar message to them.

ejurgensen commented 4 years ago

It's really great that you are looking into this. I think you could be on to something with the mdns observations, but I don't know how to interpret those messages - do you?

NorbertRoller commented 4 years ago

I checked on the web and this was mentinoned:

It looks like the mDNS responder has implemented

an option from RFC6762:

On receipt of a question for a particular name, rrtype, and rrclass, for which a responder does have one or more unique answers, the responder MAY also include an NSEC record in the Additional Record Section indicating the nonexistence of other rrtypes for that name and rrclass. Source: https://osqa-ask.wireshark.org/questions/59944/whats-the-meaning-of-these-nsec-records-in-mdns-response-packet

NorbertRoller commented 4 years ago

I have done some more checking with wireshark:

192.168.0.xx 224.0.0.251 MDNS 262 Standard query response 0x0000 TXT, cache flush NSEC, cache flush Apple TV Wozi._companion-link._tcp.local

This stops if the forked-daapd program is stopped.

So the questions are:

ejurgensen commented 4 years ago

This stuff is not directly implemented in forked-daapd, but done via Avahi (if running on Linux). So there is nothing in forked-daapd's source code doing anything each 120 sec.

On MacOS, forked-daapd supports using Bonjour DNS SD instead of Avahi, so it would be interesting to know if the problem also exists there.

ejurgensen commented 4 years ago

I now have an AE2, but it works fine. Since I am not able to reproduce on neither this AE2 or my ATV4, I am thinking there must be some other factor. What platform are you encountering this issue in? And with what version of Avahi? Then I can try to reproduce on that.

NorbertRoller commented 4 years ago

Raspberry Pi 3 Model B Plus Rev 1.3

PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian

Linux iTunesServer 4.19.113-v7+ #1300 SMP Thu Mar 26 16:53:09 GMT 2020 armv7l GNU/Linux

avahi-browse 0.7

ejurgensen commented 4 years ago

I have exactly the same RPi, but for whatever reason the issue does not reproduce on my AE2. Or perhaps I don't wait long enough.

NorbertRoller commented 4 years ago

While beeing grounded to the Homeoffice, I had it running for several days. I didn't have any drop outs on the AE2. It is just the ATV (A1625) that continue to stop streaming randomly.

ejurgensen commented 4 years ago

@NorbertRoller I think this issue is the same as #734 so to avoid having two threads on the topic I will close this one. As you can see on the other issue there is some recent progress which you might be interested in.