mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.27k stars 573 forks source link

Shairport-sync not working after updating iTunes in Windows 10 to 12.5.3 [Solved] #415

Closed diosdog closed 5 years ago

diosdog commented 8 years ago

Shairport-sync running on my VirtualBox Ubuntu 16.04 (Windows 10 host) recently stopped playing audio from iTunes on my Windows 10 machine after updating iTunes to version 12.5.3.17. The Shairport-sync server is still seen as an audio output option in iTunes, and can be selected successfully, with iTunes appearing to think that music is streaming. However, no audio plays on the server side.

I can still successfully play audio from other sources. I tested streaming audio from an iPhone running iOS 10 successfully, iTunes 12.4.3.1 on a Mac, and even streaming from another source other than iTunes (Airfoil) on the Windows machine, so the problem appears to be with the recent update to iTunes.

Note: I'm actually using the pipe output from shairport-sync to play audio to snapcast for a multiroom audio setup. But it seems the fact that this is working for Airplay sources other than the updated Windows 10 iTunes demonstrates that the pipe setup is not the issue here.

Output of shairport-sync -V: 2.8.0-openssl-Avahi-ALSA-pulse-dummy-stdout-pipe-soxr-metadata

I've included log output with statistics and verbosity=1 below. In each case, I connected to shairport-sync from an Airplay source, played audio for ~30 seconds, then disconnected.

Startup:

Nov 05 08:55:10 user-VirtualBox systemd[1]: Starting ShairportSync AirTunes receiver...
Nov 05 08:55:10 user-VirtualBox shairport-sync[3748]: pipe init
Nov 05 08:55:10 user-VirtualBox shairport-sync[3748]: Pipename is "/tmp/snapfifo"
Nov 05 08:55:10 user-VirtualBox shairport-sync[3748]: startup
Nov 05 08:55:10 user-VirtualBox shairport-sync[3748]: avahi: avahi_register.
Nov 05 08:55:10 user-VirtualBox shairport-sync[3748]: avahi: register_service.
Nov 05 08:55:10 user-VirtualBox shairport-sync[3748]: Avahi without metadata
Nov 05 08:55:10 user-VirtualBox systemd[1]: Started ShairportSync AirTunes receiver.

Streaming from iOS 10 (working):

Nov 05 08:55:19 user-VirtualBox shairport-sync[3748]: New RTSP connection on port 5000
Nov 05 08:55:19 user-VirtualBox shairport-sync[3748]: New RTSP connection on port 5000
Nov 05 08:55:19 user-VirtualBox shairport-sync[3748]: RTSP connection closed.
Nov 05 08:55:19 user-VirtualBox shairport-sync[3748]: Now closing RTSP connection.
Nov 05 08:55:19 user-VirtualBox shairport-sync[3748]: This RTSP conversation thread doesn't think it's playing for a close RTSP connection.
Nov 05 08:55:24 user-VirtualBox shairport-sync[3748]: Play connection from user agent "AirPlay/301.44.3".
Nov 05 08:55:24 user-VirtualBox shairport-sync[3748]: Active-Remote string seen: "1511905306".
Nov 05 08:55:24 user-VirtualBox shairport-sync[3748]: DACP-ID string seen: "F1548069C440B287".
Nov 05 08:55:24 user-VirtualBox shairport-sync[3748]: Connection from IPv6: [ip removed]
Nov 05 08:55:56 user-VirtualBox shairport-sync[3748]: Synchronisation disabled. Missing packets 0; late packets 62; too late packets 0; resend requests 62; min and max buffer occupancy 79 and 260.
Nov 05 08:56:26 user-VirtualBox shairport-sync[3748]: Synchronisation disabled. Missing packets 0; late packets 67; too late packets 0; resend requests 67; min and max buffer occupancy 238 and 260.
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: RTSP shutdown requested.
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: Now closing RTSP connection.
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: Shut down audio, control and timing threads
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: Control RTP thread interrupted. terminating.
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: Timing thread interrupted. terminating.
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: rtp_timing_sender thread interrupted. terminating.
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: Closed and terminated timer requester thread.
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: Timing RTP thread terminated.
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: timing thread joined
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: Audio receiver -- Server RTP thread interrupted. terminating.
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: audio thread joined
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: control thread joined
Nov 05 08:56:34 user-VirtualBox shairport-sync[3748]: Player thread exit

Streaming from iTunes 12.4.3.1 on a Mac (working):

Nov 05 08:57:05 user-VirtualBox shairport-sync[3748]: New RTSP connection on port 5000
Nov 05 08:57:05 user-VirtualBox shairport-sync[3748]: RTSP connection closed.
Nov 05 08:57:05 user-VirtualBox shairport-sync[3748]: Now closing RTSP connection.
Nov 05 08:57:05 user-VirtualBox shairport-sync[3748]: This RTSP conversation thread doesn't think it's playing for a close RTSP connection.
Nov 05 08:57:09 user-VirtualBox shairport-sync[3748]: New RTSP connection on port 5000
Nov 05 08:57:09 user-VirtualBox shairport-sync[3748]: Play connection from user agent "iTunes/12.4.3 (Macintosh; OS X 10.11.6)".
Nov 05 08:57:09 user-VirtualBox shairport-sync[3748]: Active-Remote string seen: "1727381084".
Nov 05 08:57:09 user-VirtualBox shairport-sync[3748]: DACP-ID string seen: "6CE9501DADB3B2E5".
Nov 05 08:57:09 user-VirtualBox shairport-sync[3748]: Connection from IPv4: 192.168.1.201:56160
Nov 05 08:57:41 user-VirtualBox shairport-sync[3748]: Synchronisation disabled. Missing packets 0; late packets 90; too late packets 0; resend requests 90; min and max buffer occupancy 86 and 292.
Nov 05 08:58:11 user-VirtualBox shairport-sync[3748]: Synchronisation disabled. Missing packets 0; late packets 90; too late packets 0; resend requests 90; min and max buffer occupancy 263 and 292.
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: RTSP shutdown requested.
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: Now closing RTSP connection.
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: Shut down audio, control and timing threads
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: Audio receiver -- Server RTP thread interrupted. terminating.
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: Control RTP thread interrupted. terminating.
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: Timing thread interrupted. terminating.
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: rtp_timing_sender thread interrupted. terminating.
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: Closed and terminated timer requester thread.
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: Timing RTP thread terminated.
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: timing thread joined
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: audio thread joined
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: control thread joined
Nov 05 08:58:16 user-VirtualBox shairport-sync[3748]: Player thread exit

Streaming from iTunes 12.5.3.17 on Windows 10 (not working):

Nov 05 08:58:28 user-VirtualBox shairport-sync[3748]: New RTSP connection on port 5000
Nov 05 08:58:28 user-VirtualBox shairport-sync[3748]: RTSP connection closed.
Nov 05 08:58:28 user-VirtualBox shairport-sync[3748]: Now closing RTSP connection.
Nov 05 08:58:28 user-VirtualBox shairport-sync[3748]: This RTSP conversation thread doesn't think it's playing for a close RTSP connection.
Nov 05 08:58:38 user-VirtualBox shairport-sync[3748]: New RTSP connection on port 5000
Nov 05 08:58:38 user-VirtualBox shairport-sync[3748]: Play connection from user agent "iTunes/12.5.3 (Windows; Microsoft Windows 10.0 x64 (Build 14393); x64)".
Nov 05 08:58:38 user-VirtualBox shairport-sync[3748]: Active-Remote string seen: "550913479".
Nov 05 08:58:38 user-VirtualBox shairport-sync[3748]: DACP-ID string seen: "E07B7C3826AE69C7".
Nov 05 08:58:38 user-VirtualBox shairport-sync[3748]: Connection from IPv4: 192.168.1.214:56162
Nov 05 08:58:46 user-VirtualBox shairport-sync[3748]: Aliasing of buffer index -- reset.
Nov 05 08:58:52 user-VirtualBox shairport-sync[3748]: Aliasing of buffer index -- reset.
Nov 05 08:58:58 user-VirtualBox shairport-sync[3748]: Aliasing of buffer index -- reset.
Nov 05 08:59:05 user-VirtualBox shairport-sync[3748]: Aliasing of buffer index -- reset.
Nov 05 08:59:10 user-VirtualBox shairport-sync[3748]: Aliasing of buffer index -- reset.
Nov 05 08:59:17 user-VirtualBox shairport-sync[3748]: Aliasing of buffer index -- reset.
Nov 05 08:59:23 user-VirtualBox shairport-sync[3748]: Aliasing of buffer index -- reset.
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: RTSP shutdown requested.
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: Now closing RTSP connection.
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: Shut down audio, control and timing threads
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: Audio receiver -- Server RTP thread interrupted. terminating.
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: Control RTP thread interrupted. terminating.
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: Timing thread interrupted. terminating.
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: rtp_timing_sender thread interrupted. terminating.
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: Closed and terminated timer requester thread.
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: Timing RTP thread terminated.
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: timing thread joined
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: audio thread joined
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: control thread joined
Nov 05 08:59:33 user-VirtualBox shairport-sync[3748]: Player thread exit
JamieBriers commented 8 years ago

I would like to second this. And perhaps this is the cause of another of the Issues. I was using Airplay the other morning, upgraded when itunes asked me, and immediately after, both my Shairport-Sync and my Raspberry Pi running 'MusicBox' stopped working. It sounds like they have changed something in the protocol.

mistepien commented 8 years ago

But is not shairport-sync efect of reverse engineering? If I'm right the question was not "if" but "when".

mikebrady commented 8 years ago

I've just tried this in Windows 10 Education running in a VMWare VM on a Mac Pro and it's working fine. Is it possible that some firewall settings or similar have been changed during an update?

w10

JamieBriers commented 8 years ago

Hello Mike, That's good news, i suppose. But I'm not sure what else could have changed. Ill have to fire up wireshark in the morning and see if i can detect the packets going out.

As i said, I was using iTunes when i started working that day, then i upgraded it, as well as installing icloud for windows (possible factor), when it restarted (no PC restart, just iTunes) it had stopped working. The fact that both Shairport-sync and MusicBox have the same problem, the issue must be isolated to either my Windows PC, or iTunes itself. My phone can play to both speakers, just fine. I figured they may have changed the protocol at long last, but you've debunked that theory.

Thanks for your investigations. I'll let you know any results i find.

diosdog commented 8 years ago

Hmm. I happen to have OSMC (Kodi) running on a Raspberry Pi 2. I can Airplay from iTunes on my Windows 10 machine to Kodi's Airplay receiver, but shairport-sync running on the same pi doesn't play any audio with an otherwise identical setup. It seems like that should rule out a firewall issue.

JamieBriers commented 8 years ago

My curiosity is piqued. So ive just fired up wireshark. I can see a mass of UDP packets fire over the network to the server when i start playing a song, so again, that should rule out a firewall issue. Is there any logs, or debug mode i can enable in Shairport so that we can ensure the correct information is coming across the network?

mikebrady commented 8 years ago

This is indeed curious. What version of Shairport Sync are you using? The only really accessible diagnostics are the log – set log_verbosity to 2 (or 3 if you can stand it). Shairport Sync sends packets back to iTunes for timing and stuff, so it's not sufficient for packets to go from iTunes to Shairport Sync. (Still listening to iTunes on Windows...)

mikebrady commented 8 years ago

I think the repeated messages

Nov 05 08:58:46 user-VirtualBox shairport-sync[3748]: Aliasing of buffer index -- reset.
Nov 05 08:58:52 user-VirtualBox shairport-sync[3748]: Aliasing of buffer index -- reset.

could indicate that some of the timing packets aren't getting through. Either the requests for them are not getting through or the replies are not being received.

diosdog commented 8 years ago

I think you're correct. I tried upgrading shairport-sync from 2.8.0 to 2.8.5 to see if this would help. Seeing the same behavior, and logs now include a new message:

Nov 05 12:52:37 user-VirtualBox shairport-sync[6205]: New RTSP connection from 192.168.1.214:59570 to self at 192.168.1.215:5000.
Nov 05 12:52:37 user-VirtualBox shairport-sync[6205]: Play connection from user agent "iTunes/12.5.3 (Windows; Microsoft Windows 10.0 x64 (Build 14393); x64)".
Nov 05 12:52:37 user-VirtualBox shairport-sync[6205]: Active-Remote string seen: "1814458523".
Nov 05 12:52:37 user-VirtualBox shairport-sync[6205]: DACP-ID string seen: "E07B7C3826AE69C7".
Nov 05 12:52:37 user-VirtualBox shairport-sync[6205]: Set up play connection from 192.168.1.214 to self at 192.168.1.215.
Nov 05 12:52:37 user-VirtualBox shairport-sync[6205]: total packets, missing packets, late packets, too late packets, resend requests, min buffer occupancy, max buffer occupancy
Nov 05 12:52:37 user-VirtualBox shairport-sync[6205]: Sync packet received before we got a timing packet back.
Nov 05 12:52:38 user-VirtualBox shairport-sync[6205]: Sync packet received before we got a timing packet back.
Nov 05 12:52:39 user-VirtualBox shairport-sync[6205]: Sync packet received before we got a timing packet back.
Nov 05 12:52:40 user-VirtualBox shairport-sync[6205]: Sync packet received before we got a timing packet back.
Nov 05 12:52:41 user-VirtualBox shairport-sync[6205]: Sync packet received before we got a timing packet back.
Nov 05 12:52:41 user-VirtualBox shairport-sync[6205]: Aliasing of buffer index -- reset.
Nov 05 12:52:42 user-VirtualBox shairport-sync[6205]: Sync packet received before we got a timing packet back.
Nov 05 12:52:43 user-VirtualBox shairport-sync[6205]: Sync packet received before we got a timing packet back.
Nov 05 12:52:44 user-VirtualBox shairport-sync[6205]: Sync packet received before we got a timing packet back.
Nov 05 12:52:45 user-VirtualBox shairport-sync[6205]: Sync packet received before we got a timing packet back.
Nov 05 12:52:46 user-VirtualBox shairport-sync[6205]: Aliasing of buffer index -- reset.
mikebrady commented 8 years ago

Yeah, it really seems as if timing packets are not coming back. I'm not a Windows guy, I'm afraid, but I just checked and the firewall is set for a private network, not a public or guest network. Even so, when I restored defaults and retried iTunes, I got a message about restrictions.

diosdog commented 8 years ago

You are correct! Going into Windows' Firewall settings ("Allow an app through Windows Firewall"), I had two iTunes items listed, one with only access to private networks, and another with only access to public networks. I checked both private and public checkboxes for both listings, and after applying changes everything is working.

I assume there wasn't a similar problem with the Kodi airplay receiver because it doesn't rely on the same timing synchronization or something.

Thanks for looking into this so promptly, and for all the work you've done on shairport-sync!

mikebrady commented 8 years ago

That's great! I think Kodi uses an older shairport or shairplay and they don't use the extra synchronisation protocols.

Let's leave this issue up for a while – it might help someone else.

JamieBriers commented 8 years ago

Hi all! I've managed to resolve my issues too. Going through the method from diosdog, I noticed i only had one entry on the list for iTunes. So I made sure it was public. But no luck. I clicked 'allow another app' and manually added the itunes.exe that was running, then i had two on the list and made sure both were public. Everything now works!

Very strange! Thanks for your help guys. And again, thanks for creating such an awesome program, Mike.

mikebrady commented 5 years ago

Closing the issue. Please open a new issue if necessary.