RC9 and earlier - iOS 11.3.1 iPhone 6 won't play through shairport-sync -- OSX works fine

gregs007 commented 6 years ago

Two different devices on same wireless network, same AP, etc. Behavior is that iPhone allows you to select the shairport device, it just never switches the audio over. Was running earlier version of shairport-sync (can't remember which, probably 6 months old) and I pulled/compiled latest (RC9) to try to fix it but no luck. Older version worked on earlier iOS (11.3.0 or maybe 11.2.x, can't remember).

Hardware Raspberry Pi model B:

pi@GregsOfficeStereo:/usr/local/etc $ cat /proc/cpuinfo
processor       : 0
model name      : ARMv6-compatible processor rev 7 (v6l)
BogoMIPS        : 697.95
Features        : half thumb fastmult vfp edsp java tls
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xb76
CPU revision    : 7

Hardware        : BCM2835
Revision        : 0003
Serial          : 00000000a9c8558e

Startup log:

May 25 20:02:18 GregsOfficeStereo systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
May 25 20:02:19 GregsOfficeStereo sudo[659]: pam_unix(sudo:session): session closed for user root
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: The "general" "log_verbosity" setting is deprecated. Please use the "diagnostics" "log_verbosity" setting instead.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: alsa output device name is "default".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: The processor is running little-endian.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: Version: "3.2RC9-OpenSSL-Avahi-ALSA-metadata-sysconfdir:/usr/local/etc"
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: statistics_requester status is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: daemon status is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: pid_file_path_string "/var/run/shairport-sync/shairport-sync.pid".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: deamon pid file is "/var/run/shairport-sync/shairport-sync.pid".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: rtsp listening port is 5000.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: udp base port is 6001.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: udp port range is 100.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: player name is "GregsOfficeStereo".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: backend is "(null)".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: on-start action is "(null)".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: on-stop action is "(null)".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: wait-cmd status is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: on-start returns output is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: mdns backend "(null)".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: userSuppliedLatency is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: stuffing option is "0" (0-basic, 1-soxr).
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: resync time is 0.050000 seconds.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: allow a session to be interrupted: 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: busy timeout time is 120.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: drift tolerance is 0.001995 seconds.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: password is "(null)".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: ignore_volume_control is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: volume_max_db is not set
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: disable_synchronization is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: use_mmap_if_available is 1.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: output_rate is 44100.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: audio backend desired buffer length is 0.150000 seconds.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: audio backend latency offset is 0.000000 seconds.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: volume range in dB (zero means use the range specified by the mixer): 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: zeroconf regtype is "_raop._tcp".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: decoders_supported field is 1.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: use_apple_decoder is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: alsa_use_playback_switch_for_mute is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: no special mdns service interface was requested.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: metadata enabled is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: metadata pipename is "(null)".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: metadata socket address is "(null)" port 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: metadata socket packet size is "500".
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: get-coverart is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: loudness is 0.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: loudness reference level is -20.000000
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: disable resend requests is off.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: avahi: service 'B9F517E2A844@GregsOfficeStereo' group is not yet committed.
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: avahi: request to add "_raop._tcp" service without metadata
May 25 20:02:19 GregsOfficeStereo shairport-sync[667]: avahi: service 'B9F517E2A844@GregsOfficeStereo' group is registering.
May 25 20:02:20 GregsOfficeStereo shairport-sync[667]: avahi: service 'B9F517E2A844@GregsOfficeStereo' successfully added.

Output below as I try to select "GregsOfficeStereo" for iphone output.

May 25 19:49:52 GregsOfficeStereo shairport-sync[627]: RTSP connection thread 5 deleted...
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]: New RTSP connection from [fe80::be:e6d1:d9ff:2448]:49205 to self at [fe80::2795:dfeb:de02:d4cc]:5000 on conversation thread 6.
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]: Successfully created RTSP receiver thread 6.
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:     CSeq: 0.
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:     DACP-ID: D3676CF420CF2364.
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:     Active-Remote: 3427925160.
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:     User-Agent: AirPlay/365.53.
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]: RTSP thread 6 received an RTSP Packet of type "OPTIONS":
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:   Type: "CSeq", content: "0"
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:   Type: "DACP-ID", content: "D3676CF420CF2364"
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:   Type: "Active-Remote", content: "3427925160"
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:   Type: "User-Agent", content: "AirPlay/365.53"
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]: Connection 6: OPTIONS
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]: RTSP thread 6: RTSP Response:
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:   Type: "CSeq", content: "0"
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:   Type: "Server", content: "AirTunes/105.1"
May 25 19:49:52 GregsOfficeStereo shairport-sync[627]:   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
May 25 19:49:53 GregsOfficeStereo shairport-sync[627]: New RTSP connection from 10.69.100.253:49206 to self at 10.69.100.58:5000 on conversation thread 7.
May 25 19:49:53 GregsOfficeStereo shairport-sync[627]: Successfully created RTSP receiver thread 7.
May 25 19:49:53 GregsOfficeStereo shairport-sync[627]: RTSP conversation thread 7 -- connection closed.
May 25 19:49:53 GregsOfficeStereo shairport-sync[627]: Synchronously terminate playing thread of RTSP conversation thread 7.
May 25 19:49:53 GregsOfficeStereo shairport-sync[627]: player thread of RTSP conversation 7 is already deleted.
May 25 19:49:53 GregsOfficeStereo shairport-sync[627]: Successful termination of playing thread of RTSP conversation thread 7.
May 25 19:49:53 GregsOfficeStereo shairport-sync[627]: Request termination of RTSP conversation thread 7.
May 25 19:49:53 GregsOfficeStereo shairport-sync[627]: Connection 7: RTSP thread terminated.

Then when I switch back to the iPhone output.

May 25 19:49:56 GregsOfficeStereo shairport-sync[627]: RTSP conversation thread 6 -- connection closed.
May 25 19:49:56 GregsOfficeStereo shairport-sync[627]: Synchronously terminate playing thread of RTSP conversation thread 6.
May 25 19:49:56 GregsOfficeStereo shairport-sync[627]: player thread of RTSP conversation 6 is already deleted.
May 25 19:49:56 GregsOfficeStereo shairport-sync[627]: Successful termination of playing thread of RTSP conversation thread 6.
May 25 19:49:56 GregsOfficeStereo shairport-sync[627]: Request termination of RTSP conversation thread 6.
May 25 19:49:56 GregsOfficeStereo shairport-sync[627]: Connection 6: RTSP thread terminated.

By Contrast when I connect from MacBook Pro running 10.13.4 it actually works and looks like this:

May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: New RTSP connection from [fe80::424:7f7e:7147:79c0]:52660 to self at [fe80::2795:dfeb:de02:d4cc]:5000 on conversation thread 8.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: Successfully created RTSP receiver thread 8.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: New RTSP connection from 10.69.100.254:52661 to self at 10.69.100.58:5000 on conversation thread 9.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: Successfully created RTSP receiver thread 9.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     CSeq: 0.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     DACP-ID: 7EB98A6BB739AA76.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     Active-Remote: 1364931448.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     User-Agent: AirPlay/365.53.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: RTSP thread 8 received an RTSP Packet of type "OPTIONS":
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "CSeq", content: "0"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "DACP-ID", content: "7EB98A6BB739AA76"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "Active-Remote", content: "1364931448"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "User-Agent", content: "AirPlay/365.53"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: Connection 8: OPTIONS
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: RTSP thread 8: RTSP Response:
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "CSeq", content: "0"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "Server", content: "AirTunes/105.1"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: RTSP conversation thread 9 -- connection closed.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: Synchronously terminate playing thread of RTSP conversation thread 9.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: player thread of RTSP conversation 9 is already deleted.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: Successful termination of playing thread of RTSP conversation thread 9.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: Request termination of RTSP conversation thread 9.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: Connection 9: RTSP thread terminated.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     CSeq: 1.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     DACP-ID: 7EB98A6BB739AA76.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     Active-Remote: 1364931448.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     User-Agent: AirPlay/365.53.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: RTSP thread 8 received an RTSP Packet of type "OPTIONS":
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "CSeq", content: "1"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "DACP-ID", content: "7EB98A6BB739AA76"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "Active-Remote", content: "1364931448"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "User-Agent", content: "AirPlay/365.53"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: Connection 8: OPTIONS
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: RTSP thread 8: RTSP Response:
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "CSeq", content: "1"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "Server", content: "AirTunes/105.1"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     Apple-Challenge: pX/BHNtH1YEGHtMUDyY02w==.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     CSeq: 2.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     DACP-ID: 7EB98A6BB739AA76.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     Active-Remote: 1364931448.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:     User-Agent: AirPlay/365.53.
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]: RTSP thread 8 received an RTSP Packet of type "OPTIONS":
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "Apple-Challenge", content: "pX/BHNtH1YEGHtMUDyY02w=="
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "CSeq", content: "2"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "DACP-ID", content: "7EB98A6BB739AA76"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "Active-Remote", content: "1364931448"
May 25 19:53:35 GregsOfficeStereo shairport-sync[627]:   Type: "User-Agent", content: "AirPlay/365.53"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]: Connection 8: OPTIONS
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]: RTSP thread 8: RTSP Response:
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:   Type: "Apple-Response", content: "PnLloeJQ2Fn8DTy6pfpnJA8fE6nebX2gH1Xg5jLavjqFBdYAnXDTAor2L4i8vvf/9ub6ffr1cYK1F6rPLl3Bzwgz9W1DeB3xZ7oL7MKpAag7P+uD3VjEXRJzpG18PJC2ZbJsnL0jMdQGbQ0gQNyrPyj4mO/uz291hpe1GSYRkELBi45J/4sJjB6akmnRZYI+GxKaMPB8acKov1pwo7Rvf+xLwxTCRs4kWEY5J3a83RY3Bh8YVINl50JqBQfj0N8NJntNbEpWfewu10YWccVppZRDQ3kExr9abuX4vQ6fHYPKXHAoGljHan6SmZfq0liGRGwInbavDe9mGrAgy846Mg"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:   Type: "CSeq", content: "2"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:   Type: "Server", content: "AirTunes/105.1"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:     Content-Length: 680.
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:     Content-Type: application/sdp.
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:     CSeq: 3.
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:     DACP-ID: 7EB98A6BB739AA76.
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:     Active-Remote: 1364931448.
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:     User-Agent: AirPlay/365.53.
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]: RTSP thread 8 received an RTSP Packet of type "ANNOUNCE":
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:   Type: "Content-Length", content: "680"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:   Type: "Content-Type", content: "application/sdp"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:   Type: "CSeq", content: "3"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:   Type: "DACP-ID", content: "7EB98A6BB739AA76"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:   Type: "Active-Remote", content: "1364931448"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]:   Type: "User-Agent", content: "AirPlay/365.53"
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]: Connection 8: ANNOUNCE
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]: RTSP conversation thread 8 has acquired play lock.
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]: Minimum latency 11025 specified
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]: Maximum latency 88200 specified
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]: Play connection from user agent "AirPlay/365.53" on RTSP conversation thread 8.
May 25 19:53:36 GregsOfficeStereo shairport-sync[627]: AirPlay version 365 detected.

etc, etc etc...

mikebrady commented 6 years ago

Thanks for the post. It's mighty curious. If you'd be kind enough to switch to the development branch and then set log verbosity to 2 and enable statistics, then try it on the iPhone, we might get a better idea of what is happening... Also, what app are you using on the iPhone -- is it the Music app?

gregs007 commented 6 years ago

Ugh. Can’t believe I didn’t try it with a different app. Music app works and so does google play music. Amazon music unlimited doesn’t work though. Do you still want me to install develop branch and gather the logs to rule out an issue with shairport-sync?

mikebrady commented 6 years ago

It's not really necessary, thanks, unless you want really to. It's a fair bit of effort. I haven't actually used Amazon Music -- not even sure it's available in my country -- but it would be worth just checking that the YouTube app works okay for you. It works fine for me, but it has a really flaky and -- I believe -- buggy AirPlay implementation. But generally, if Shairport Sync works with other apps, it's not likely to be a Shairport Sync issue.

mikebrady commented 6 years ago

Out of curiosity, I checked and indeed I can indeed use Amazon Music, and am using it right now from an iPhone 6 to a RPi 3B running the latest development version, essentially the same as RC10. It seems to be working perfectly, but I'll keep checking. It works with the built-in audio and with a Pimoroni Phat DAC.

gregs007 commented 6 years ago

Thanks for following up. I'll pull development compile and test, then report my results.

gregs007 commented 6 years ago

Cloned development branch built/installed. No change. Re-installed Amazon Music and it worked fine. Really sorry for the fire drill. Closing out.

mikebrady commented 6 years ago

No worries.

mikebrady / shairport-sync

RC9 and earlier - iOS 11.3.1 iPhone 6 won't play through shairport-sync -- OSX works fine #706