mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.02k stars 567 forks source link

[Problem]: AirPlay 2 experimentation issues #1871

Open gearhead opened 3 days ago

gearhead commented 3 days ago

What happened?

I tried 2 ways to connect to shairport-sync when it was advertising AirPlay2 and neither connected. I added these 3 lines to the shairport-sync.conf:

port = 7000;
airplay_device_id_offset = 2;
regtype = "_airplay._tcp";

It advertises as AirPlay2, but when I try connecting from an iPhone or with OwnTone, it immediately disconnects and I get no audio. If I comment out the regtype line, it defaults to AirPlay1 and plays audio.

If you need more log or different log or whatever, I can test it. I have an iphone14 and owntone running here.

This log is from an attempt to connect form an iPhone 14:

Relevant log output form an iphone14 connection:

0.000097648 "rtsp.c:5733" Connection 3: New connection from 192.168.2.16:49505 to self at 192.168.2.201:7000.
         0.000120760 "rtsp.c:5749" Successfully created RTSP receiver thread 3.
         0.000041851 "rtsp.c:5273" mutex_lock "&conns_lock".
         0.000053278 "rtsp.c:667" mutex_lock "&conns_lock".
         0.000019926 "common.c:1709" mutex_unlock "&conns_lock" at "rtsp.c:5280".
         0.000053537 "rtsp.c:782" msg_init message 1
         0.000006278 "rtsp.c:896" RTSP Message Received: "GET /info RTSP/1.0".
         0.000006185 "rtsp.c:927"     X-Apple-ProtocolVersion: 1.
         0.000003352 "rtsp.c:927"     Content-Length: 70.
         0.000003648 "rtsp.c:927"     Content-Type: application/x-apple-binary-plist.
         0.000003537 "rtsp.c:927"     CSeq: 0.
         0.000003333 "rtsp.c:927"     User-Agent: AirPlay/770.8.1.
         0.000005037 "rtsp.c:782" msg_init message 2
         0.000003760 "rtsp.c:5299" Connection 3: Received an RTSP Packet of type "GET":
         0.000004166 "rtsp.c:5301"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000002982 "rtsp.c:5301"   Type: "Content-Length", content: "70"
         0.000002981 "rtsp.c:5301"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000003204 "rtsp.c:5301"   Type: "CSeq", content: "0"
         0.000003000 "rtsp.c:5301"   Type: "User-Agent", content: "AirPlay/770.8.1"
         0.000016333 "rtsp.c:5301"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
        <key>qualifier</key>
        <array>
                <string>txtAirPlay</string>
        </array>
</dict>
</plist>
--
         0.000008963 "rtsp.c:2081" Connection 3: GET /info :: Content-Length 70
         0.000004056 "rtsp.c:2083" GET request
         0.000002722 "rtsp.c:2083"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000002778 "rtsp.c:2083"   Type: "Content-Length", content: "70"
         0.000002796 "rtsp.c:2083"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000002908 "rtsp.c:2083"   Type: "CSeq", content: "0"
        0.000002777 "rtsp.c:2083"   Type: "User-Agent", content: "AirPlay/770.8.1"
         0.000006426 "rtsp.c:2083"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
        <key>qualifier</key>
        <array>
                <string>txtAirPlay</string>
        </array>
</dict>
</plist>
--
         0.000003945 "rtsp.c:1678" GET /info:
         0.000003074 "rtsp.c:1678"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000003315 "rtsp.c:1678"   Type: "Content-Length", content: "70"
         0.000002777 "rtsp.c:1678"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000002778 "rtsp.c:1678"   Type: "CSeq", content: "0"
         0.000002778 "rtsp.c:1678"   Type: "User-Agent", content: "AirPlay/770.8.1"
         0.000005259 "rtsp.c:1678"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
        <key>qualifier</key>
        <array>
                <string>txtAirPlay</string>
        </array>
</dict>
</plist>
--
         0.000003852 "rtsp.c:1687" Connection 3: GET_INFO: Source AirPlay Version is: 770.8.1.
         0.000003278 "rtsp.c:1705" Connection 3: GET /info -- doesn't include  Active-Remote information.
         0.000003222 "rtsp.c:1724" Connection 3: GET /info -- doesn't include DACP-ID string information.
         0.000005148 "rtsp.c:1751" GET /info Stage 1: qualifier: txtAirPlay
         0.000196926 "rtsp.c:1838" GET /info Stage 1 Response:
         0.000009130 "rtsp.c:1838"   Response Code: 501.
         0.000003241 "rtsp.c:1838"   Type: "CSeq", content: "0"
         0.000002851 "rtsp.c:1838"   Type: "Server", content: "AirTunes/366.0"
         0.000003000 "rtsp.c:1838"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000038537 "rtsp.c:1838"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
        <key>audioLatencies</key>
        <array>
                <dict>
                        <key>inputLatencyMicros</key>
                        <integer>0</integer>
                        <key>outputLatencyMicros</key>
                        <integer>400000</integer>
                        <key>type</key>
                        <integer>100</integer>
                </dict>
                <dict>
                        <key>audioType</key>
                        <string>default</string>
                        <key>inputLatencyMicros</key>
                        <integer>0</integer>
                        <key>outputLatencyMicros</key>
                        <integer>400000</integer>
                        <key>type</key>
                        <integer>100</integer>
                </dict>
               <dict>
                        <key>audioType</key>
                        <string>media</string>
                        <key>inputLatencyMicros</key>
                        <integer>0</integer>
                        <key>outputLatencyMicros</key>
                        <integer>400000</integer>
                        <key>type</key>
                        <integer>100</integer>
                </dict>
                <dict>
                        <key>audioType</key>
                        <string>media</string>
                        <key>inputLatencyMicros</key>
                        <integer>0</integer>
                        <key>outputLatencyMicros</key>
                        <integer>400000</integer>
                        <key>type</key>
                        <integer>102</integer>
                </dict>
        </array>
        <key>keepAliveLowPower</key>
        <true/>
        <key>keepAliveSendStatsAsBody</key>
        <true/>
        <key>manufacturer</key>
        <string>Shairport Sync</string>
        <key>nameIsFactoryDefault</key>
        <false/>
        <key>protocolVersion</key>
        <string>1.1</string>
        <key>sdk</key>
        <string>AirPlay;2.0.2</string>
        <key>sourceVersion</key>
        <string>366.0</string>
        <key>statusFlags</key>
        <integer>4</integer>
       <key>txtAirPlay</key>
        <data>
        BWFjbD0wGmRldmljZWlkPWQ4OjNhOmRkOmQyOmFlOjNjG2ZlYXR1cmVzPTB4NDA1RkNB
        MDAsMHgxQzM0MAdyc2Y9MHgwCWZsYWdzPTB4NBRtb2RlbD1TaGFpcnBvcnQgU3luYw1t
        YW51ZmFjdHVyZXI9DXNlcmlhbE51bWJlcj0NcHJvdG92ZXJzPTEuMQ1zcmN2ZXJzPTM2
        Ni4wJ3BpPTliMGZiMDAxLTA0ZTYtNGRlMi1hYzIwLWMzODdkYzgyN2Y2ZShnaWQ9OWIw
        ZmIwMDEtMDRlNi00ZGUyLWFjMjAtYzM4N2RjODI3ZjZlBmdjZ2w9MENwaz0zMzA4NTA0
        MjBmNjg1MmY3MDk1NGY3ZjgxZmExNTIwZjhiYzc1NDFlYzU0ZTdmYTQ3MTBjZTc5YTAz
        ODY4NzQ0
        </data>
        <key>features</key>
        <integer>496155702053376</integer>
        <key>deviceID</key>
        <string>d8:3a:dd:d2:ae:3c</string>
        <key>pi</key>
        <string>9b0fb001-04e6-4de2-ac20-c387dc827f6e</string>
        <key>name</key>
        <string>Pi5</string>
        <key>model</key>
        <string>Shairport Sync</string>
</dict>
</plist>
--
         0.000014537 "rtsp.c:5360" Connection 3: RTSP Response:
         0.000003889 "rtsp.c:5361"   Response Code: 200.
         0.000002778 "rtsp.c:5361"   Type: "CSeq", content: "0"
         0.000002796 "rtsp.c:5361"   Type: "Server", content: "AirTunes/366.0"
         0.000002778 "rtsp.c:5361"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000033426 "rtsp.c:5361"   Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/Prope
rtyList-1.0.dtd">
<plist version="1.0">
<dict>
        <key>audioLatencies</key>
        <array>
                <dict>
                        <key>inputLatencyMicros</key>
                        <integer>0</integer>
                        <key>outputLatencyMicros</key>
                        <integer>400000</integer>
                        <key>type</key>
                        <integer>100</integer>
                </dict>
                <dict>
                        <key>audioType</key>
                        <string>default</string>
                        <key>inputLatencyMicros</key>
                        <integer>0</integer>
                        <key>outputLatencyMicros</key>
                        <integer>400000</integer>
                        <key>type</key>
                        <integer>100</integer>
                </dict>
                <dict>
                        <key>audioType</key>
                        <string>media</string>
                        <key>inputLatencyMicros</key>
                        <integer>0</integer>
                        <key>outputLatencyMicros</key>
                        <integer>400000</integer>
                        <key>type</key>
                        <integer>100</integer>
                </dict>
                <dict>
                        <key>audioType</key>
                        <string>media</string>
                        <key>inputLatencyMicros</key>
                       <integer>400000</integer>
                        <key>type</key>
                        <integer>102</integer>
                </dict>
        </array>
        <key>keepAliveLowPower</key>
        <true/>
        <key>keepAliveSendStatsAsBody</key>
        <true/>
        <key>manufacturer</key>
        <string>Shairport Sync</string>
        <key>nameIsFactoryDefault</key>
        <false/>
        <key>protocolVersion</key>
        <string>1.1</string>
        <key>sdk</key>
        <string>AirPlay;2.0.2</string>
        <key>sourceVersion</key>
        <string>366.0</string>
        <key>statusFlags</key>
        <integer>4</integer>
        <key>txtAirPlay</key>
        <data>
        BWFjbD0wGmRldmljZWlkPWQ4OjNhOmRkOmQyOmFlOjNjG2ZlYXR1cmVzPTB4NDA1RkNB
        MDAsMHgxQzM0MAdyc2Y9MHgwCWZsYWdzPTB4NBRtb2RlbD1TaGFpcnBvcnQgU3luYw1t
        YW51ZmFjdHVyZXI9DXNlcmlhbE51bWJlcj0NcHJvdG92ZXJzPTEuMQ1zcmN2ZXJzPTM2
        Ni4wJ3BpPTliMGZiMDAxLTA0ZTYtNGRlMi1hYzIwLWMzODdkYzgyN2Y2ZShnaWQ9OWIw
        ZmIwMDEtMDRlNi00ZGUyLWFjMjAtYzM4N2RjODI3ZjZlBmdjZ2w9MENwaz0zMzA4NTA0
        MjBmNjg1MmY3MDk1NGY3ZjgxZmExNTIwZjhiYzc1NDFlYzU0ZTdmYTQ3MTBjZTc5YTAz
        ODY4NzQ0
        </data>
        <key>features</key>
        <integer>496155702053376</integer>
        <key>deviceID</key>
        <string>d8:3a:dd:d2:ae:3c</string>
        <key>pi</key>
        <string>9b0fb001-04e6-4de2-ac20-c387dc827f6e</string>
        <key>name</key>
        <string>Pi5</string>
        <key>model</key>
        <string>Shairport Sync</string>
</dict>
</plist>
--
         0.000008926 "rtsp.c:1536" Responding with content of length 901
         0.000032204 "rtsp.c:872" msg_free freed message 2
         0.000007278 "rtsp.c:872" msg_free freed message 1
         0.000003314 "rtsp.c:5273" mutex_lock "&conns_lock".
         0.000003389 "common.c:1709" mutex_unlock "&conns_lock" at "rtsp.c:5280".
         0.000504445 "common.c:1709" mutex_unlock "&conns_lock" at "rtsp.c:689".
         0.005464796 "rtsp.c:782" msg_init message 3
         0.000023944 "rtsp.c:896" RTSP Message Received: "POST /pair-verify RTSP/1.0".
         0.000008575 "rtsp.c:927"     X-Apple-AbsoluteTime: 741225562.
         0.000004296 "rtsp.c:927"     X-Apple-HKP: 6.
         0.000003018 "rtsp.c:927"     X-Apple-Client-Name: Kristen’s iPhone.
         0.000004426 "rtsp.c:927"     X-Apple-PD: 1.
         0.000002889 "rtsp.c:927"     Content-Length: 37.
         0.000002982 "rtsp.c:927"     Content-Type: application/octet-stream.
         0.000003018 "rtsp.c:927"     CSeq: 1.
         0.000003352 "rtsp.c:927"     User-Agent: AirPlay/770.8.1.
         0.000005500 "rtsp.c:782" msg_init message 4
         0.000004167 "rtsp.c:5299" Connection 3: Received an RTSP Packet of type "POST":
         0.000003592 "rtsp.c:5301"   Type: "X-Apple-AbsoluteTime", content: "741225562"
         0.000003000 "rtsp.c:5301"   Type: "X-Apple-HKP", content: "6"
         0.000002778 "rtsp.c:5301"   Type: "X-Apple-Client-Name", content: "Kristen’s iPhone"
         0.000002870 "rtsp.c:5301"   Type: "X-Apple-PD", content: "1"
         0.000002778 "rtsp.c:5301"   Type: "Content-Length", content: "37"
         0.000002778 "rtsp.c:5301"   Type: "Content-Type", content: "application/octet-stream"
...

System Information.

###### System info ######
Linux version 6.6.31+rpt-rpi-2712 (serge@raspberrypi.com) (gcc-12 (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #1 SMP PREEMPT Debian 1:6.6.31-1+rpt1 (2024-05-29)

Hardware model: Raspberry Pi 5 Model B Rev 1.0
Linux version:  Linux 6.6.31+rpt-rpi-2712 RPiOS-bookworm aarch64 (64bit)
System time:    Thu Jun 27 03:03:17 PM CDT 2024
System load:    1.89 1.04 0.42 2/256 8402
HW platform:    RaspberryPi2 (08)

Using alsa only (no pulse or pipewire)

Configuration Information.

# shairport-sync --displayConfig
>> Display Config Start.

From "uname -a":
 Linux pi5 6.6.31+rpt-rpi-2712 #1 SMP PREEMPT Debian 1:6.6.31-1+rpt1 (2024-05-29) aarch64 GNU/Linux

From /etc/os-release:
 Debian GNU/Linux 12 (bookworm)

From /sys/firmware/devicetree/base/model:
 Raspberry Pi 5 Model B Rev 1.0

Shairport Sync Version String:
 4.3.4-dev-15-g0412a840-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-jack-stdout-pipe-soxr-metadata-mqtt-dbus-sysconfdir:/etc

Command Line:
 shairport-sync --displayConfig

Configuration File:
 /etc/shairport-sync.conf

Configuration File Settings:
 general : 
 {
   name = "Pi5";
   interpolation = "soxr";
   output_backend = "alsa";
   port = 7000;
   airplay_device_id_offset = 2;
   regtype = "_airplay._tcp";
   alac_decoder = "apple";
 };
 sessioncontrol : 
 {
   run_this_before_play_begins = "/srv/http/command/airplay_toggle on";
   run_this_after_play_ends = "/srv/http/command/airplay_toggle off";
   wait_for_completion = "yes";
 };
 alsa : 
 {
   output_device = "sysdefault:CARD=vc4hdmi0";
   mixer_control_name = "PCM";
   mixer_device = "hw:CARD=vc4hdmi0";
   output_rate = 44100;
   output_format = "S16";
 };
 pw : 
 {
 };
 pipe : 
 {
   name = "/tmp/shairport-sync-output-pipe";
 };
 metadata : 
 {
   enabled = "yes";
   include_cover_art = "yes";
   pipe_name = "/tmp/shairport-sync-metadata";
 };

>> Display Config End.
>> Goodbye!

PulseAudio or PipeWire installed?

How did you install Shairport Sync?

Built from source

Check previous issues

mikebrady commented 2 days ago

TBH, I’m not sure what you’re aiming for here.

But this is working for me from an iPhone:

shairport-sync -- -d hw:0
         0.000806482 "shairport.c:2275" Startup in AirPlay 2 mode, with features 0x405fca00,0x1c340 on device "d8:3a:dd:c3:fe:7a".
         0.000057815 "shairport.c:2314" Version String: "4.3.4-dev-15-g0412a840-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-metadata-dbus-sysconfdir:/etc"
         0.000012277 "shairport.c:2333" Command Line: "./shairport-sync".
         0.000105778 "shairport.c:2369" Log Verbosity is 1.
         0.000036445 "audio_alsa.c:1082" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000025740 "audio_alsa.c:1371" alsa: disable_standby_mode is "never".
         0.000008519 "audio_alsa.c:1375" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000008963 "audio_alsa.c:1377" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000010944 "audio_alsa.c:1417" alsa: output device name is "hw:0".
         0.000066834 "shairport.c:2437" disable_resend_requests is off.
         0.000013592 "shairport.c:2438" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000009685 "shairport.c:2442" statistics_requester status is 1.
         0.000008463 "shairport.c:2447" rtsp listening port is 7000.
         0.000007648 "shairport.c:2448" udp base port is 6001.
         0.000007612 "shairport.c:2449" udp port range is 10.
         0.000007555 "shairport.c:2450" player name is "RaspberryPi5B".
         0.000007908 "shairport.c:2451" backend is "alsa".
         0.000007333 "shairport.c:2452" run_this_before_play_begins action is "(null)".
         0.000007685 "shairport.c:2453" run_this_after_play_ends action is "(null)".
         0.000007648 "shairport.c:2454" wait-cmd status is 0.
         0.000007611 "shairport.c:2455" run_this_before_play_begins may return output is 0.
         0.000007593 "shairport.c:2456" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000007944 "shairport.c:2458" run_this_before_entering_active_state action is  "(null)".
         0.000007834 "shairport.c:2460" run_this_after_exiting_active_state action is  "(null)".
         0.000007537 "shairport.c:2462" active_state_timeout is  10.000000 seconds.
         0.000009407 "shairport.c:2463" mdns backend "(null)".
         0.000007796 "shairport.c:2465" interpolation setting is "auto".
         0.000007537 "shairport.c:2469" interpolation soxr_delay_threshold is 30000000.
         0.000007982 "shairport.c:2470" resync time is 0.050000 seconds.
         0.000008444 "shairport.c:2471" resync recovery time is 0.100000 seconds.
         0.000008482 "shairport.c:2472" allow a session to be interrupted: 0.
         0.000007981 "shairport.c:2473" busy timeout time is 0.
         0.000008556 "shairport.c:2474" drift tolerance is 0.002000 seconds.
         0.000008426 "shairport.c:2475" password is not set.
         0.000008018 "shairport.c:2476" default airplay volume is: -24.000000.
         0.000008686 "shairport.c:2477" high threshold airplay volume is: -16.000000.
         0.000008666 "shairport.c:2479" check for higher-than-threshold volume for new play session is disabled.
         0.000008537 "shairport.c:2485" ignore_volume_control is 0.
         0.000008093 "shairport.c:2489" volume_max_db is not set
         0.000007796 "shairport.c:2490" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000009093 "shairport.c:2492" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000008518 "shairport.c:2496" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000008463 "shairport.c:2498" disable_synchronization is 0.
         0.000007796 "shairport.c:2499" use_mmap_if_available is 1.
         0.000007908 "shairport.c:2500" output_format automatic selection is enabled.
         0.000008167 "shairport.c:2504" output_rate automatic selection is enabled.
         0.000008074 "shairport.c:2508" audio backend desired buffer length is 0.200000 seconds.
         0.000008426 "shairport.c:2510" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000008555 "shairport.c:2512" audio backend latency offset is 0.000000 seconds.
         0.000008333 "shairport.c:2514" audio backend silence lead-in time is "auto".
         0.000007908 "shairport.c:2518" zeroconf regtype is "_airplay._tcp".
         0.000007944 "shairport.c:2519" decoders_supported field is 1.
         0.000007871 "shairport.c:2520" use_apple_decoder is 0.
         0.000007814 "shairport.c:2521" alsa_use_hardware_mute is 0.
         0.000007834 "shairport.c:2525" no special mdns service interface was requested.
         0.000011666 "shairport.c:2528" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000010204 "shairport.c:2535" metadata enabled is 1.
         0.000008148 "shairport.c:2536" metadata pipename is "/tmp/shairport-sync-metadata".
         0.000008167 "shairport.c:2537" metadata socket address is "(null)" port 0.
         0.000008259 "shairport.c:2539" metadata socket packet size is "500".
         0.000008148 "shairport.c:2540" get-coverart is 1.
         0.000007834 "shairport.c:2558" loudness is 0.
         0.000008092 "shairport.c:2559" loudness reference level is -20.000000
         0.000043648 "rtsp.c:4220" metadata pipe name is "/tmp/shairport-sync-metadata".
         0.001049315 "shairport.c:2686" NQPTP is online.
         0.004240889 "dbus-service.c:1183" *warning: could not acquire a Shairport Sync native D-Bus interface "org.gnome.ShairportSync.i8834" on the system bus.
         1.495604703 "shairport.c:255" "soxr" interpolation has been chosen.
        10.158362327 "rtsp.c:2944" Connection 1: AP2 PTP connection from fd33:6082:3ec8:d547:493:c67e:ba49:b952:64463 ("Mike Brady's iPhone") to self at fd33:6082:3ec8:d547:fe5a:6db:fe4:2c38:7000.
         4.692372405 "rtsp.c:3301" Connection 1: SETUP AP2 no Active-Remote information  the SETUP Record.
         0.000035352 "rtsp.c:3320" Connection 1: SETUP AP2 doesn't include DACP-ID string information.
         0.656413610 "player.c:2834" Connection 1: Playback started at frame 3449448188 -- AirPlay 2 Buffered.
         7.931969922 "player.c:2653" Sync Error ms | Net Sync PPM | All Sync PPM | Min DAC Queue | Min Buffers | Min Buffer Size | Output FPS (r) | Output FPS (c)
         0.000030907 "player.c:2653"         -0.03            0.0            0.0            7411            46              260k              N/A              N/A
         8.003931069 "player.c:2653"          0.29            0.0            0.0            7422            46             3934k         44097.24         44096.92
         8.003313218 "player.c:2653"          1.67          -53.8           53.8            7451            46             3797k         44098.24         44097.92
         8.005149143 "player.c:2653"          2.00          -31.2           31.2            7497            46             3789k         44098.23         44097.91
^C         2.164407999 "rtsp.c:531" Connection 1: cancelled.
         0.011297296 "player.c:1796" Connection 1: Playback stopped. Total playing time 00:00:34. Output: 44098.23 (raw), 44097.91 (corrected) frames per second.
         0.001956778 "rtsp.c:542" Connection 1: joined.
         0.000637111 "shairport.c:1725" normal exit
shairport-sync --displayConfig
         0.000838444 "shairport.c:2126" >> Display Config Start.
         0.001193371 "shairport.c:2126" 
         0.000015277 "shairport.c:2126" From "uname -a":
         0.000004463 "shairport.c:2126"  Linux RaspberryPi5B 6.6.31+rpt-rpi-2712 #1 SMP PREEMPT Debian 1:6.6.31-1+rpt1 (2024-05-29) aarch64 GNU/Linux
         0.002652574 "shairport.c:2126" 
         0.000040852 "shairport.c:2126" From /etc/os-release:
         0.000004371 "shairport.c:2126"  Debian GNU/Linux 12 (bookworm)
         0.001164055 "shairport.c:2126" 
         0.000016408 "shairport.c:2126" From /sys/firmware/devicetree/base/model:
         0.000003481 "shairport.c:2126"  Raspberry Pi 5 Model B Rev 1.0
         0.000015500 "shairport.c:2126" 
         0.000011815 "shairport.c:2126" Shairport Sync Version String:
         0.000007963 "shairport.c:2126"  4.3.4-dev-15-g0412a840-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-metadata-dbus-sysconfdir:/etc
         0.000009222 "shairport.c:2126" 
         0.000007815 "shairport.c:2126" Command Line:
         0.000007759 "shairport.c:2126"  ./shairport-sync --displayConfig
         0.000020296 "shairport.c:2126" 
         0.000007982 "shairport.c:2126" Configuration File:
         0.000007481 "shairport.c:2126"  /etc/shairport-sync.conf
         0.000007167 "shairport.c:2126" 
         0.000065370 "shairport.c:2126" Configuration File Settings:
         0.000009408 "shairport.c:2126"  general : 
         0.000007370 "shairport.c:2126"  {
         0.000007056 "shairport.c:2126"    port = 7000;
         0.000007129 "shairport.c:2126"    airplay_device_id_offset = 2;
         0.000007204 "shairport.c:2126"    regtype = "_airplay._tcp";
         0.000006981 "shairport.c:2126"  };
         0.000007111 "shairport.c:2126"  alsa : 
         0.000005575 "shairport.c:2126"  {
         0.000002944 "shairport.c:2126"    output_device = "hw:0";
         0.000002778 "shairport.c:2126"  };
         0.000002648 "shairport.c:2126"  pw : 
         0.000002481 "shairport.c:2126"  {
         0.000002556 "shairport.c:2126"  };
         0.000002796 "shairport.c:2126"  diagnostics : 
         0.000002667 "shairport.c:2126"  {
         0.000002537 "shairport.c:2126"    statistics = "yes";
         0.000002870 "shairport.c:2126"    log_verbosity = 1;
         0.000002760 "shairport.c:2126"  };
         0.000002629 "shairport.c:2126" 
         0.000002482 "shairport.c:2126" >> Display Config End.
         0.000002907 "shairport.c:2128" >> Goodbye!
         0.000020667 "shairport.c:1725" normal exit
gearhead commented 2 days ago

Mike,

I do not know what I was doing wrong or right, but today, it played once from the iPhone, for a bit. I did not play a whole song, but it did play for a minute or so and I stopped the stream. I tried it again and it would not play. From a look at the log, it is causing a restart of the shairport-sync service. I started it at 16:49:30 and tried to connect then it restarted at 16:50:07:

Jun 28 16:49:30 pi5 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000819074 "shairport.c:2275" Startup in AirPlay 2 mode, with features 0x405fca00,0x1c340 on device "d8:3a:dd:d2:ae:3c".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000058871 "shairport.c:2314" Version String: "4.3.4-dev-15-g0412a840-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-jack-stdout-pipe-soxr-metadata-mqtt-dbus-sysconfdir:/etc"
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000005944 "shairport.c:2333" Command Line: "/usr/bin/shairport-sync -c /etc/shairport-sync.conf".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000017944 "shairport.c:2340" libsodium initialised.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000100315 "shairport.c:2365" libgcrypt initialised.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000006722 "shairport.c:2369" Log Verbosity is 2.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000005797 "audio_alsa.c:1065" alsa: init() -- alsa_backend_state => abm_disconnected.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000004018 "audio_alsa.c:1082" alsa: alsa_maximum_stall_time of 0.200000 sec.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000014982 "audio_alsa.c:1236" alsa output rate is 44100 frames per second
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000007685 "audio_alsa.c:1371" alsa: disable_standby_mode is "never".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000003018 "audio_alsa.c:1375" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002482 "audio_alsa.c:1377" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000005648 "audio_alsa.c:1417" alsa: output device name is "sysdefault:CARD=vc4hdmi0".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000134167 "shairport.c:2404" The processor is running little-endian.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000013444 "shairport.c:2437" disable_resend_requests is off.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000005130 "shairport.c:2438" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000000352 "shairport.c:2442" statistics_requester status is 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002686 "shairport.c:2447" rtsp listening port is 7000.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002000 "shairport.c:2448" udp base port is 6001.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002000 "shairport.c:2449" udp port range is 10.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002370 "shairport.c:2450" player name is "Pi5".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002296 "shairport.c:2451" backend is "alsa".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002222 "shairport.c:2452" run_this_before_play_begins action is "/srv/http/command/airplay_toggle on".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000003704 "shairport.c:2453" run_this_after_play_ends action is "/srv/http/command/airplay_toggle off".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002463 "shairport.c:2454" wait-cmd status is 1.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001870 "shairport.c:2455" run_this_before_play_begins may return output is 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002130 "shairport.c:2456" run_this_if_an_unfixable_error_is_detected action is "(null)".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000003593 "shairport.c:2458" run_this_before_entering_active_state action is  "(null)".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000005018 "shairport.c:2460" run_this_after_exiting_active_state action is  "(null)".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000003371 "shairport.c:2462" active_state_timeout is  10.000000 seconds.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000005629 "shairport.c:2463" mdns backend "(null)".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002111 "shairport.c:2464" userSuppliedLatency is 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002556 "shairport.c:2465" interpolation setting is "auto".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002722 "shairport.c:2469" interpolation soxr_delay_threshold is 30000000.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000003037 "shairport.c:2470" resync time is 0.050000 seconds.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000004019 "shairport.c:2471" resync recovery time is 0.100000 seconds.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000006666 "shairport.c:2472" allow a session to be interrupted: 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000004019 "shairport.c:2473" busy timeout time is 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002555 "shairport.c:2474" drift tolerance is 0.002000 seconds.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000004629 "audio_alsa.c:2110" keep_dac_busy is now "no"
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002334 "shairport.c:2475" password is not set.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000029203 "shairport.c:2476" default airplay volume is: -24.000000.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000004797 "shairport.c:2477" high threshold airplay volume is: -16.000000.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002370 "shairport.c:2479" check for higher-than-threshold volume for new play session is disabled.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002037 "shairport.c:2485" ignore_volume_control is 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002556 "shairport.c:2489" volume_max_db is not set
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001944 "shairport.c:2490" volume range in dB (zero means use the range specified by the mixer): 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002370 "shairport.c:2492" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002334 "shairport.c:2496" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002222 "shairport.c:2498" disable_synchronization is 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001963 "shairport.c:2499" use_mmap_if_available is 1.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001778 "shairport.c:2500" output_format automatic selection is disabled.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002148 "shairport.c:2503" output_format is "S16".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001944 "shairport.c:2504" output_rate automatic selection is disabled.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001926 "shairport.c:2507" output_rate is 44100.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001889 "shairport.c:2508" audio backend desired buffer length is 0.200000 seconds.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002704 "shairport.c:2510" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002407 "shairport.c:2512" audio backend latency offset is 0.000000 seconds.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002352 "shairport.c:2514" audio backend silence lead-in time is "auto".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002296 "shairport.c:2518" zeroconf regtype is "_airplay._tcp".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002019 "shairport.c:2519" decoders_supported field is 3.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001815 "shairport.c:2520" use_apple_decoder is 1.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001833 "shairport.c:2521" alsa_use_hardware_mute is 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001778 "shairport.c:2525" no special mdns service interface was requested.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000009074 "shairport.c:2528" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002870 "shairport.c:2535" metadata enabled is 1.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001889 "shairport.c:2536" metadata pipename is "/tmp/shairport-sync-metadata".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002537 "shairport.c:2537" metadata socket address is "(null)" port 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002278 "shairport.c:2539" metadata socket packet size is "500".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000003037 "shairport.c:2540" get-coverart is 1.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002056 "shairport.c:2543" mqtt is disabled.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001981 "shairport.c:2544" mqtt hostname is (null), port is 1883.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002037 "shairport.c:2545" mqtt topic is /Pi5.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002093 "shairport.c:2546" mqtt will not publish raw metadata.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001796 "shairport.c:2547" mqtt will not publish parsed metadata.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000002037 "shairport.c:2548" mqtt will not publish cover Art.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001870 "shairport.c:2549" mqtt remote control is disabled.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001760 "shairport.c:2558" loudness is 0.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000001926 "shairport.c:2559" loudness reference level is -20.000000
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000071537 "rtsp.c:4220" metadata pipe name is "/tmp/shairport-sync-metadata".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000015833 "rtsp.c:373" Creating metadata queue "pipe".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000055722 "rtsp.c:373" Creating metadata queue "multicast".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000046259 "rtsp.c:373" Creating metadata queue "hub".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000048538 "rtsp.c:373" Creating metadata queue "mqtt".
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000691240 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp T"
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000347056 "ptp-utilities.c:165" ptp_shm_interface_open with mapped_addr = 0
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000032000 "ptp-utilities.c:196" ptp_shm_interface_open -- success!
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000006092 "shairport.c:2686" NQPTP is online.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000650704 "activity_monitor.c:163" am_state: am_inactive
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.002605056 "mdns_avahi.c:220" avahi: service 'D83ADDD2AE3C@Pi5' group is not yet committed.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.001087277 "mdns_avahi.c:277" avahi: avahi_entry_group_commit 0
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000106000 "mdns_avahi.c:477" avahi_dacp_monitor_start Avahi DACP monitor successfully started
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000087056 "mdns_avahi.c:224" avahi: service 'D83ADDD2AE3C@Pi5' group is registering.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.001041704 "dbus-service.c:610" >> setting loudness threshold to -20.000000.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000045426 "dbus-service.c:623" >> setting drift tolerance to 0.002000 seconds.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000007129 "dbus-service.c:636" >> setting volume to -24.0000.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000009389 "dbus-service.c:1021" >> ALACDecoder set to "apple"
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000004759 "dbus-service.c:1030" >> Active set to "false"
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000005667 "dbus-service.c:1035" >> disable standby mode set to "off"
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000004759 "dbus-service.c:1056" >> interpolation set to "auto" (soxr support built in)
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000007908 "dbus-service.c:518" >> deactivating disable standby
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000004481 "dbus-service.c:600" >> deactivating loudness
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000022056 "dbus-service.c:503" >> log verbosity set to 2.
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000005185 "dbus-service.c:488" >> stop logging statistics
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000005556 "dbus-service.c:448" >> stop including elapsed time in logs
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000004537 "dbus-service.c:458" >> start including delta time in logs
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000004444 "dbus-service.c:471" >> start including file and line in logs
Jun 28 16:49:30 pi5 shairport-sync[302252]:          0.000013037 "dbus-service.c:1175" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
Jun 28 16:49:31 pi5 shairport-sync[302252]:          0.763879203 "mdns_avahi.c:191" avahi: service 'D83ADDD2AE3C@Pi5' successfully added.
Jun 28 16:49:32 pi5 shairport-sync[302252]:          0.729899055 "shairport.c:248" soxr_delay: 1335184 nanoseconds, soxr_delay_threshold: 30 milliseconds.
Jun 28 16:49:32 pi5 shairport-sync[302252]:          0.000065630 "shairport.c:255" "soxr" interpolation has been chosen.
Jun 28 16:49:58 pi5 shairport-sync[302252]:         26.176425799 "rtsp.c:720" No active connections.
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000181037 "rtsp.c:5733" Connection 1: New connection from 192.168.2.16:49681 to self at 192.168.2.201:7000.
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.015843500 "rtsp.c:2290" Connection 1: handle_pair-setup Content-Length 9
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.040463426 "rtsp.c:2290" Connection 1: handle_pair-setup Content-Length 457
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.030466093 "rtsp.c:2911" Connection 1: SETUP (AirPlay 2)
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000079907 "rtsp.c:2931" Connection 1 SETUP: No "streams" array has been found -- create an event thread and open a TCP port.
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000005796 "rtsp.c:2944" Connection 1: AP2 PTP connection from 192.168.2.16:49681 ("Kristen’s iPhone") to self at 192.168.2.201:7000.
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000006889 "rtsp.c:586" Connection 1: request to acquire principal_conn.
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000005371 "ptp-utilities.c:165" ptp_shm_interface_open with mapped_addr = 140734588469248
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000008759 "ptp-utilities.c:200" ptp_shm_interface_open -- already open!
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000004981 "rtsp.c:3032" Updated groupContainsGroupLeader to 0
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000102926 "metadata_hub.c:570" MH Client IP set to: "192.168.2.16"
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000184260 "dbus-service.c:226" Build metadata
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000014463 "metadata_hub.c:622" MH Server IP set to: "192.168.2.201"
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000030833 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp T 192.168.2.16"
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000020593 "dbus-service.c:226" Build metadata
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000275796 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp B"
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000129648 "rtsp.c:3142" Connection 1: TCP PTP event port opened: 58683.
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000214815 "rtp.c:1572" Connection 1: AP2 Event Receiver started
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000079852 "rtsp.c:3169" Connection 1: SETUP mdns_update on PTP stream.
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000804685 "metadata_hub.c:578" MH Client Name set to: "Kristen’s iPhone"
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.000107907 "dbus-service.c:226" Build metadata
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.011888463 "rtp.c:1584" Connection 1: rtp_event_receiver accepted a connection on socket 13 and moved to a new socket 14.
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.005361593 "rtsp.c:4436" Connection 1: current volume (-24.000000) requested
Jun 28 16:49:58 pi5 shairport-sync[302252]:          0.004709000 "rtsp.c:1616" Connection 1: RECORD on PTP stream
Jun 28 16:50:04 pi5 shairport-sync[302252]:          6.540562274 "rtsp.c:3660" Connection 1: request to set AirPlay Volume to: -144.000000.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000118759 "dbus-service.c:636" >> setting volume to -144.0000.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000018333 "player.c:3386" player_volume_without_notification: volume mode is 0, airplay_volume is -144.000000, software mute is enabled.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.016974722 "rtsp.c:2780" Connection 1: TEARDOWN 2 PTP stream.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000085500 "rtsp.c:2782" TEARDOWN:
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000005019 "rtsp.c:2782"   Type: "Content-Length", content: "42"
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000003889 "rtsp.c:2782"   Type: "Content-Type", content: "application/x-apple-binary-plist"
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000002555 "rtsp.c:2782"   Type: "CSeq", content: "15"
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000003297 "rtsp.c:2782"   Type: "User-Agent", content: "AirPlay/770.8.1"
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000014481 "rtsp.c:2782"   Content Plist (as XML):
Jun 28 16:50:04 pi5 shairport-sync[302252]: --
Jun 28 16:50:04 pi5 shairport-sync[302252]: <?xml version="1.0" encoding="UTF-8"?>
Jun 28 16:50:04 pi5 shairport-sync[302252]: <!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
Jun 28 16:50:04 pi5 shairport-sync[302252]: <plist version="1.0">
Jun 28 16:50:04 pi5 shairport-sync[302252]: <dict/>
Jun 28 16:50:04 pi5 shairport-sync[302252]: </plist>
Jun 28 16:50:04 pi5 shairport-sync[302252]: --
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000005334 "rtsp.c:2799" Connection 1: TEARDOWN PTP stream -- close the connection.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000005222 "rtsp.c:2706" Connection 1: TEARDOWN PTP stream connection.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000002815 "rtsp.c:2726" Connection 1: TEARDOWN PTP stream Delete Event Thread.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000170296 "rtp.c:1564" Connection 1: AP2 Event Receiver Cleanup.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000057296 "rtsp.c:2734" Connection 1: TEARDOWN PTP stream Close Event Socket.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000030815 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp T"
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000574407 "rtsp.c:2766" Connection 1: TEARDOWN mdns_update on PTP stream.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.001067037 "rtsp.c:2773" Connection 1: TEARDOWN PTP stream -- close the connection complete
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.031871149 "rtsp.c:1335" Connection 1: Connection closed by client.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000054351 "rtsp.c:5116" Connection 1: PTP stream rtsp_conversation_thread_func_cleanup_function called.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000011371 "rtsp.c:2706" Connection 1: TEARDOWN PTP stream connection.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000007037 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp T"
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000377481 "rtsp.c:2773" Connection 1: TEARDOWN PTP stream -- close the connection complete
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000016037 "rtsp.c:5148" Connection 1: terminating -- closing RTSP connection socket 12: from 192.168.2.16:49681 to self at 192.168.2.201:7000.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000234500 "rtsp.c:5215" Connection 1: Closed.
Jun 28 16:50:04 pi5 shairport-sync[302252]:          0.000016815 "rtsp.c:5437" Connection 1: RTSP thread exit.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.103643185 "rtsp.c:703" Found RTSP connection thread 1 in a non-running state.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000057093 "rtsp.c:706" Connection 1: deleted.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000063741 "rtsp.c:5733" Connection 2: New connection from 192.168.2.16:49683 to self at 192.168.2.201:7000.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.015576926 "rtsp.c:2290" Connection 2: handle_pair-setup Content-Length 9
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.029800870 "rtsp.c:2290" Connection 2: handle_pair-setup Content-Length 457
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.026554407 "rtsp.c:2911" Connection 2: SETUP (AirPlay 2)
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000091760 "rtsp.c:2931" Connection 2 SETUP: No "streams" array has been found -- create an event thread and open a TCP port.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000015925 "rtsp.c:2944" Connection 2: AP2 PTP connection from 192.168.2.16:49683 ("Kristen’s iPhone") to self at 192.168.2.201:7000.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000007260 "rtsp.c:586" Connection 2: request to acquire principal_conn.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000032852 "ptp-utilities.c:165" ptp_shm_interface_open with mapped_addr = 140734588469248
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000007259 "ptp-utilities.c:200" ptp_shm_interface_open -- already open!
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000005037 "rtsp.c:3032" Updated groupContainsGroupLeader to 0
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000123629 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp T 192.168.2.16"
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000132463 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp B"
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000138019 "rtsp.c:3142" Connection 2: TCP PTP event port opened: 58681.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000075370 "rtp.c:1572" Connection 2: AP2 Event Receiver started
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000099797 "rtsp.c:3169" Connection 2: SETUP mdns_update on PTP stream.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.009154111 "rtp.c:1584" Connection 2: rtp_event_receiver accepted a connection on socket 13 and moved to a new socket 14.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.010139092 "rtsp.c:4436" Connection 2: current volume (-144.000000) requested
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.003976389 "rtsp.c:1616" Connection 2: RECORD on PTP stream
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.007835556 "rtsp.c:2510" Connection 2: POST /command Content-Length 128
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.005541555 "rtsp.c:3660" Connection 2: request to set AirPlay Volume to: -27.000000.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000163315 "dbus-service.c:636" >> setting volume to -27.0000.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000021833 "player.c:3486" Software attenuation set to -7407.692308, i.e 12.960859 out of 65,536, for airplay volume of -27.000000
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000008908 "loudness.c:47" Volume: -74.1 dB - Loudness gain @10Hz: 27.0 dB
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000038278 "player.c:3527" player_volume_without_notification: volume mode is 0, airplay volume is -27.00, software_attenuation dB: -74.08, hardware_attenuation dB: 0.00, muting is disabled.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000095444 "dbus-service.c:226" Build metadata
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.006924704 "rtsp.c:2510" Connection 2: POST /command Content-Length 1649
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.166298222 "rtsp.c:2911" Connection 2: SETUP (AirPlay 2)
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000109222 "rtsp.c:3254" Connection 2: SETUP on PTP stream. A "streams" array has been found
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000012278 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp B"
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000420981 "rtsp.c:3282" Connection 2: UDP control port opened: 34862.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000178500 "rtsp.c:3301" Connection 2: SETUP AP2 no Active-Remote information  the SETUP Record.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000008167 "rtsp.c:3320" Connection 2: SETUP AP2 doesn't include DACP-ID string information.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000004648 "rtsp.c:3388" Connection 2. AP2 Buffered Audio Stream.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000002148 "rtsp.c:3389" Buffered Audio Stream SETUP incoming message
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000002741 "rtsp.c:3389"   Type: "Content-Length", content: "265"
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000002426 "rtsp.c:3389"   Type: "Content-Type", content: "application/x-apple-binary-plist"
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000002074 "rtsp.c:3389"   Type: "CSeq", content: "14"
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000001889 "rtsp.c:3389"   Type: "User-Agent", content: "AirPlay/770.8.1"
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000026389 "rtsp.c:3389"   Content Plist (as XML):
Jun 28 16:50:05 pi5 shairport-sync[302252]: --
Jun 28 16:50:05 pi5 shairport-sync[302252]: <?xml version="1.0" encoding="UTF-8"?>
Jun 28 16:50:05 pi5 shairport-sync[302252]: <!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
Jun 28 16:50:05 pi5 shairport-sync[302252]: <plist version="1.0">
Jun 28 16:50:05 pi5 shairport-sync[302252]: <dict>
Jun 28 16:50:05 pi5 shairport-sync[302252]:         <key>streams</key>
Jun 28 16:50:05 pi5 shairport-sync[302252]:         <array>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                 <dict>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <key>audioMode</key>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <string>default</string>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <key>ct</key>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <integer>4</integer>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <key>streamConnectionID</key>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <integer>5956544622685210580</integer>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <key>spf</key>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <integer>1024</integer>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <key>shk</key>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <data>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         PJwgj7ntXi2uWoiyjqmXlAAFU1WpSwBeQbatdSu7Gr8=
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         </data>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <key>supportsDynamicStreamID</key>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <true/>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <key>audioFormat</key>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <integer>4194304</integer>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <key>audioFormatIndex</key>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <integer>22</integer>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <key>type</key>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                         <integer>103</integer>
Jun 28 16:50:05 pi5 shairport-sync[302252]:                 </dict>
Jun 28 16:50:05 pi5 shairport-sync[302252]:         </array>
Jun 28 16:50:05 pi5 shairport-sync[302252]: </dict>
Jun 28 16:50:05 pi5 shairport-sync[302252]: </plist>
Jun 28 16:50:05 pi5 shairport-sync[302252]: --
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000026074 "rtsp.c:3406" Connection 2: TCP Buffered Audio port opened: 48923.
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000004778 "activity_monitor.c:64" abeg
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000151555 "activity_monitor.c:167" am_state: am_active
Jun 28 16:50:05 pi5 shairport-sync[302252]:          0.000011519 "dbus-service.c:226" Build metadata
Jun 28 16:50:07 pi5 shairport-sync[302252]:          1.910004628 "audio_alsa.c:960" alsa: hardware mixer prepare
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.004504222 "audio_alsa.c:1599" alsa: update timestamps available
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000034723 "audio_alsa.c:257" alsa: precision delay timing is not available because it's not definitely a hardware device.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000004685 "audio_alsa.c:820" PCM handle name = 'sysdefault:CARD=vc4hdmi0'
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002741 "audio_alsa.c:834" alsa device parameters:
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002944 "audio_alsa.c:837"   access type = MMAP_INTERLEAVED
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003241 "audio_alsa.c:840"   format = 'S16_LE' (Signed 16 bit Little Endian)
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002778 "audio_alsa.c:844"   subformat = 'STD' (Standard)
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002537 "audio_alsa.c:848"   number of channels = 2
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002833 "audio_alsa.c:851"   number of significant bits = 16
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002167 "audio_alsa.c:859"   rate = 44100 frames per second (precisely).
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002222 "audio_alsa.c:868"   precise (rational) rate = 44100.000 frames per second (i.e. 44100/1).
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000004815 "audio_alsa.c:882"   period_time = 5804 us (>).
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002259 "audio_alsa.c:892"   period_size = 256 frames (precisely).
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003630 "audio_alsa.c:908"   buffer_time = 1486077 us (>).
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002963 "audio_alsa.c:921"   buffer_size = 65536 frames (>).
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003388 "audio_alsa.c:931"   periods_per_buffer = 256 (precisely).
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000004537 "audio_alsa.c:1980" alsa: prepare() -- opened output device
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000129482 "player.c:3621" Connection 2: player_play.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000824907 "dbus-service.c:226" Build metadata
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.001625630 "dacp.c:411" set_dacp_server_information set IP to "192.168.2.16" and DACP id to "".
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000939111 "player.c:2254" Set initial volume to -27.000000.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000460148 "player.c:3527" player_volume_without_notification: volume mode is 1, airplay volume is -27.00, software_attenuation dB: 0.00, hardware_attenuation dB: -39.23, muting is disabled.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000013278 "player.c:2257" Play begin
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.014837111 "rtsp.c:1872" FLUSHBUFFERED request
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000072500 "rtsp.c:1872"   Type: "Content-Length", content: "87"
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000010019 "rtsp.c:1872"   Type: "Content-Type", content: "application/x-apple-binary-plist"
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003796 "rtsp.c:1872"   Type: "CSeq", content: "16"
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003833 "rtsp.c:1872"   Type: "User-Agent", content: "AirPlay/770.8.1"
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000044093 "rtsp.c:1872"   Content Plist (as XML):
Jun 28 16:50:07 pi5 shairport-sync[302252]: --
Jun 28 16:50:07 pi5 shairport-sync[302252]: <?xml version="1.0" encoding="UTF-8"?>
Jun 28 16:50:07 pi5 shairport-sync[302252]: <!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
Jun 28 16:50:07 pi5 shairport-sync[302252]: <plist version="1.0">
Jun 28 16:50:07 pi5 shairport-sync[302252]: <dict>
Jun 28 16:50:07 pi5 shairport-sync[302252]:         <key>flushUntilSeq</key>
Jun 28 16:50:07 pi5 shairport-sync[302252]:         <integer>4939065</integer>
Jun 28 16:50:07 pi5 shairport-sync[302252]:         <key>flushUntilTS</key>
Jun 28 16:50:07 pi5 shairport-sync[302252]:         <integer>4128403524</integer>
Jun 28 16:50:07 pi5 shairport-sync[302252]: </dict>
Jun 28 16:50:07 pi5 shairport-sync[302252]: </plist>
Jun 28 16:50:07 pi5 shairport-sync[302252]: --
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000020037 "rtsp.c:1883" Can't find a flushFromSeq
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000004870 "rtsp.c:1895" Can't find a flushFromTS
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000004500 "rtsp.c:1908" flushUntilSeq is 4939065.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003185 "rtsp.c:1916" flushUntilTS is 4128403524.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000006130 "rtsp.c:1963" Immediate Flush Requested
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.040434852 "rtsp.c:2780" Connection 2: TEARDOWN 2 PTP stream.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.001153981 "rtsp.c:2782" TEARDOWN:
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000050982 "rtsp.c:2782"   Type: "Content-Length", content: "84"
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000005129 "rtsp.c:2782"   Type: "Content-Type", content: "application/x-apple-binary-plist"
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003963 "rtsp.c:2782"   Type: "CSeq", content: "17"
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003149 "rtsp.c:2782"   Type: "User-Agent", content: "AirPlay/770.8.1"
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000055166 "rtsp.c:2782"   Content Plist (as XML):
Jun 28 16:50:07 pi5 shairport-sync[302252]: --
Jun 28 16:50:07 pi5 shairport-sync[302252]: <?xml version="1.0" encoding="UTF-8"?>
Jun 28 16:50:07 pi5 shairport-sync[302252]: <!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
Jun 28 16:50:07 pi5 shairport-sync[302252]: <plist version="1.0">
Jun 28 16:50:07 pi5 shairport-sync[302252]: <dict>
Jun 28 16:50:07 pi5 shairport-sync[302252]:         <key>streams</key>
Jun 28 16:50:07 pi5 shairport-sync[302252]:         <array>
Jun 28 16:50:07 pi5 shairport-sync[302252]:                 <dict>
Jun 28 16:50:07 pi5 shairport-sync[302252]:                         <key>streamID</key>
Jun 28 16:50:07 pi5 shairport-sync[302252]:                         <integer>0</integer>
Jun 28 16:50:07 pi5 shairport-sync[302252]:                         <key>type</key>
Jun 28 16:50:07 pi5 shairport-sync[302252]:                         <integer>103</integer>
Jun 28 16:50:07 pi5 shairport-sync[302252]:                 </dict>
Jun 28 16:50:07 pi5 shairport-sync[302252]:         </array>
Jun 28 16:50:07 pi5 shairport-sync[302252]: </dict>
Jun 28 16:50:07 pi5 shairport-sync[302252]: </plist>
Jun 28 16:50:07 pi5 shairport-sync[302252]: --
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000018871 "rtsp.c:2791" Connection 2: TEARDOWN PTP stream -- close the stream.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000008407 "player.c:3644" Connection 2: player_stop.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000136482 "audio_alsa.c:1883" alsa: do_close()
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.010536666 "audio_alsa.c:1896" alsa: do_close() -- closing alsa handle
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000196537 "player.c:1823" Cancelling AP2 timing, control and audio threads...
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000015519 "player.c:1832" Connection 2: Delete Buffered Audio Stream thread
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000504129 "rtp.c:2010" Buffered TCP Reader Thread Exit via Cleanup.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000300371 "rtp.c:2183" Buffered Audio Receiver Cleanup Start.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000107926 "rtp.c:2186" Connection 2: TCP Buffered Audio port closed: 48923.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000042370 "rtp.c:2189" Buffered Audio Receiver Cleanup Done.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000110963 "player.c:1840" Connection 862737684: Delete AirPlay 2 Control thread
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000072796 "rtp.c:1633" Connection 2: AP2 Control Receiver Cleanup.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000021204 "rtp.c:1635" Connection 2: UDP control port 34862 closed.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000025444 "rtp.c:1322" Connection 2: Clear anchor information.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000323575 "player.c:432" 1024 buffers allocated, 1024 buffers released.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000005462 "player.c:1893" Connection 2: player terminated.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000044241 "player.c:3659" Connection 2: player_stop successful.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000013204 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp E"
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.004543963 "dbus-service.c:226" Build metadata
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.372095685 "shairport.c:1750" exit on SIGTERM
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000242111 "rtsp.c:5463" rtsp_listen_loop_cleanup_handler called.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000064593 "rtsp.c:531" Connection 2: cancelled.
Jun 28 16:50:07 pi5 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.001485555 "rtsp.c:5116" Connection 2: PTP stream rtsp_conversation_thread_func_cleanup_function called.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000036945 "rtsp.c:2706" Connection 2: TEARDOWN PTP stream connection.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000005518 "rtsp.c:2726" Connection 2: TEARDOWN PTP stream Delete Event Thread.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000660222 "rtp.c:1564" Connection 2: AP2 Event Receiver Cleanup.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000124611 "rtsp.c:2734" Connection 2: TEARDOWN PTP stream Close Event Socket.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000034241 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp T"
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000287500 "rtsp.c:2766" Connection 2: TEARDOWN mdns_update on PTP stream.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.001627611 "rtsp.c:2773" Connection 2: TEARDOWN PTP stream -- close the connection complete
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000039426 "rtsp.c:5148" Connection 2: terminating -- closing RTSP connection socket 12: from 192.168.2.16:49683 to self at 192.168.2.201:7000.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000246704 "rtsp.c:5215" Connection 2: Closed.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000252981 "rtsp.c:542" Connection 2: joined.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000020000 "rtsp.c:5469" closing socket 6.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000030111 "rtsp.c:5469" closing socket 7.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000134204 "shairport.c:1588" exit function called...
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000016982 "shairport.c:1598" Stopping the activity monitor.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000005722 "activity_monitor.c:243" activity_monitor_stop begin. state: 2, player_state: 0.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000008778 "activity_monitor.c:84" aend
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000132092 "dbus-service.c:226" Build metadata
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000703648 "activity_monitor.c:250" activity_monitor_stop complete
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000050167 "shairport.c:1600" Stopping the activity monitor done.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000005074 "shairport.c:1603" Stopping DACP Monitor
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003704 "dacp.c:991" dacp_monitor_stop
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000078204 "shairport.c:1605" Stopping DACP Monitor Done
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000008259 "shairport.c:1616" Stopping D-Bus service
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003611 "dbus-service.c:1219" stopping dbus service
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.001167555 "shairport.c:1618" Stopping D-Bus service done
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000087056 "shairport.c:1621" Stopping D-Bus Loop Thread
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000029259 "shairport.c:1556" g_main_loop thread exit
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000266685 "shairport.c:1629" Stopping D-Bus Loop Thread Done
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000016519 "shairport.c:1634" Stopping metadata hub
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003815 "shairport.c:1636" Stopping metadata done
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002648 "shairport.c:1640" Stopping metadata
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000003426 "rtsp.c:4271" metadata_stop called.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000145815 "rtsp.c:393" Deleting metadata queue "mqtt".
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000188815 "rtsp.c:393" Deleting metadata queue "hub".
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000137222 "rtsp.c:393" Deleting metadata queue "multicast".
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000118185 "rtsp.c:393" Deleting metadata queue "pipe".
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000014481 "shairport.c:1642" Stopping metadata done
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000005037 "shairport.c:1646" Deinitialise the audio backend.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000011482 "audio_alsa.c:1442" Cancel buffer monitor thread.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000108074 "shairport.c:1648" Deinitialise the audio backend done.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000010907 "shairport.c:1654" Waiting for SoXr timecheck to terminate...
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000017371 "shairport.c:1657" Waiting for SoXr timecheck to terminate done
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000006889 "ptp-utilities.c:208" ptp_shm_interface_close
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000045296 "mdns_avahi.c:531" avahi_dacp_monitor_stop Avahi DACP monitor successfully stopped
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000007481 "mdns_avahi.c:428" avahi_unregister.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002204 "mdns_avahi.c:430" avahi: stop the threaded poll.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000094315 "mdns_avahi.c:434" avahi: free the client.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000488426 "mdns_avahi.c:440" avahi: free the threaded poll.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000056333 "mdns_avahi.c:448" avahi: free the service name.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000006389 "mdns_avahi.c:455" avahi: free the ap2 service_name.
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000002593 "mdns_avahi.c:461" avahi free text_record_string_list
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000005463 "mdns_avahi.c:468" avahi free ap_2text_record_string_list
Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.000009037 "shairport.c:1725" normal exit
Jun 28 16:50:07 pi5 systemd[1]: shairport-sync.service: Deactivated successfully.
Jun 28 16:50:07 pi5 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Jun 28 16:50:07 pi5 systemd[1]: shairport-sync.service: Consumed 1.966s CPU time.
Jun 28 16:50:07 pi5 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000939018 "shairport.c:2275" Startup in AirPlay 2 mode, with features 0x405fca00,0x1c340 on device "d8:3a:dd:d2:ae:3c".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000045630 "shairport.c:2314" Version String: "4.3.4-dev-15-g0412a840-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-jack-stdout-pipe-soxr-metadata-mqtt-dbus-sysconfdir:/etc"
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000005481 "shairport.c:2333" Command Line: "/usr/bin/shairport-sync -c /etc/shairport-sync.conf".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000024352 "shairport.c:2340" libsodium initialised.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000091222 "shairport.c:2365" libgcrypt initialised.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000012315 "shairport.c:2369" Log Verbosity is 2.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000007963 "audio_alsa.c:1065" alsa: init() -- alsa_backend_state => abm_disconnected.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000005278 "audio_alsa.c:1082" alsa: alsa_maximum_stall_time of 0.200000 sec.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000019444 "audio_alsa.c:1236" alsa output rate is 44100 frames per second
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000006352 "audio_alsa.c:1371" alsa: disable_standby_mode is "never".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002074 "audio_alsa.c:1375" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002648 "audio_alsa.c:1377" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000003185 "audio_alsa.c:1417" alsa: output device name is "sysdefault:CARD=vc4hdmi0".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000112519 "audio_alsa.c:2110" keep_dac_busy is now "no"
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000504741 "shairport.c:2404" The processor is running little-endian.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000016963 "shairport.c:2437" disable_resend_requests is off.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000003185 "shairport.c:2438" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002370 "shairport.c:2442" statistics_requester status is 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002111 "shairport.c:2447" rtsp listening port is 7000.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002149 "shairport.c:2448" udp base port is 6001.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001907 "shairport.c:2449" udp port range is 10.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002148 "shairport.c:2450" player name is "Pi5".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001778 "shairport.c:2451" backend is "alsa".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001907 "shairport.c:2452" run_this_before_play_begins action is "/srv/http/command/airplay_toggle on".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002204 "shairport.c:2453" run_this_after_play_ends action is "/srv/http/command/airplay_toggle off".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002167 "shairport.c:2454" wait-cmd status is 1.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001981 "shairport.c:2455" run_this_before_play_begins may return output is 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002611 "shairport.c:2456" run_this_if_an_unfixable_error_is_detected action is "(null)".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002037 "shairport.c:2458" run_this_before_entering_active_state action is  "(null)".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002000 "shairport.c:2460" run_this_after_exiting_active_state action is  "(null)".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002315 "shairport.c:2462" active_state_timeout is  10.000000 seconds.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000004630 "shairport.c:2463" mdns backend "(null)".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002685 "shairport.c:2464" userSuppliedLatency is 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002352 "shairport.c:2465" interpolation setting is "auto".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000003648 "shairport.c:2469" interpolation soxr_delay_threshold is 30000000.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001944 "shairport.c:2470" resync time is 0.050000 seconds.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002334 "shairport.c:2471" resync recovery time is 0.100000 seconds.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002037 "shairport.c:2472" allow a session to be interrupted: 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002296 "shairport.c:2473" busy timeout time is 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002111 "shairport.c:2474" drift tolerance is 0.002000 seconds.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002130 "shairport.c:2475" password is not set.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001926 "shairport.c:2476" default airplay volume is: -24.000000.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002240 "shairport.c:2477" high threshold airplay volume is: -16.000000.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002167 "shairport.c:2479" check for higher-than-threshold volume for new play session is disabled.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001852 "shairport.c:2485" ignore_volume_control is 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002555 "shairport.c:2489" volume_max_db is not set
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001741 "shairport.c:2490" volume range in dB (zero means use the range specified by the mixer): 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001963 "shairport.c:2492" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002593 "shairport.c:2496" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002241 "shairport.c:2498" disable_synchronization is 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001796 "shairport.c:2499" use_mmap_if_available is 1.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001833 "shairport.c:2500" output_format automatic selection is disabled.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002241 "shairport.c:2503" output_format is "S16".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002018 "shairport.c:2504" output_rate automatic selection is disabled.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001778 "shairport.c:2507" output_rate is 44100.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001963 "shairport.c:2508" audio backend desired buffer length is 0.200000 seconds.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002148 "shairport.c:2510" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000003111 "shairport.c:2512" audio backend latency offset is 0.000000 seconds.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002760 "shairport.c:2514" audio backend silence lead-in time is "auto".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002333 "shairport.c:2518" zeroconf regtype is "_airplay._tcp".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002037 "shairport.c:2519" decoders_supported field is 3.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002037 "shairport.c:2520" use_apple_decoder is 1.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002407 "shairport.c:2521" alsa_use_hardware_mute is 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002093 "shairport.c:2525" no special mdns service interface was requested.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000011463 "shairport.c:2528" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000003000 "shairport.c:2535" metadata enabled is 1.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002000 "shairport.c:2536" metadata pipename is "/tmp/shairport-sync-metadata".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002222 "shairport.c:2537" metadata socket address is "(null)" port 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002222 "shairport.c:2539" metadata socket packet size is "500".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001963 "shairport.c:2540" get-coverart is 1.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002000 "shairport.c:2543" mqtt is disabled.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001945 "shairport.c:2544" mqtt hostname is (null), port is 1883.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002148 "shairport.c:2545" mqtt topic is /Pi5.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001926 "shairport.c:2546" mqtt will not publish raw metadata.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001870 "shairport.c:2547" mqtt will not publish parsed metadata.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000002093 "shairport.c:2548" mqtt will not publish cover Art.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001796 "shairport.c:2549" mqtt remote control is disabled.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001815 "shairport.c:2558" loudness is 0.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000001907 "shairport.c:2559" loudness reference level is -20.000000
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000095075 "rtsp.c:4220" metadata pipe name is "/tmp/shairport-sync-metadata".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000015462 "rtsp.c:373" Creating metadata queue "pipe".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000053538 "rtsp.c:373" Creating metadata queue "multicast".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000033314 "rtsp.c:373" Creating metadata queue "hub".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000044297 "rtsp.c:373" Creating metadata queue "mqtt".
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000936426 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp T"
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000432555 "ptp-utilities.c:165" ptp_shm_interface_open with mapped_addr = 0
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000036000 "ptp-utilities.c:196" ptp_shm_interface_open -- success!
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000007685 "shairport.c:2686" NQPTP is online.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000818074 "activity_monitor.c:163" am_state: am_inactive
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.006489149 "dbus-service.c:610" >> setting loudness threshold to -20.000000.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000047425 "dbus-service.c:623" >> setting drift tolerance to 0.002000 seconds.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000012260 "dbus-service.c:636" >> setting volume to -24.0000.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000012981 "dbus-service.c:1021" >> ALACDecoder set to "apple"
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000006796 "dbus-service.c:1030" >> Active set to "false"
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000007630 "dbus-service.c:1035" >> disable standby mode set to "off"
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000005167 "dbus-service.c:1056" >> interpolation set to "auto" (soxr support built in)
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000010129 "dbus-service.c:518" >> deactivating disable standby
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000003815 "mdns_avahi.c:220" avahi: service 'D83ADDD2AE3C@Pi5' group is not yet committed.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000013482 "dbus-service.c:600" >> deactivating loudness
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000039648 "dbus-service.c:503" >> log verbosity set to 2.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000007074 "dbus-service.c:488" >> stop logging statistics
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000007574 "dbus-service.c:448" >> stop including elapsed time in logs
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000008759 "dbus-service.c:458" >> start including delta time in logs
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000009556 "dbus-service.c:471" >> start including file and line in logs
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000035000 "dbus-service.c:1175" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.001518815 "mdns_avahi.c:277" avahi: avahi_entry_group_commit 0
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000145481 "mdns_avahi.c:477" avahi_dacp_monitor_start Avahi DACP monitor successfully started
Jun 28 16:50:07 pi5 shairport-sync[302813]:          0.000098741 "mdns_avahi.c:224" avahi: service 'D83ADDD2AE3C@Pi5' group is registering.
Jun 28 16:50:08 pi5 shairport-sync[302813]:          0.880014518 "mdns_avahi.c:191" avahi: service 'D83ADDD2AE3C@Pi5' successfully added.
Jun 28 16:50:09 pi5 shairport-sync[302813]:          0.611771203 "shairport.c:248" soxr_delay: 1609243 nanoseconds, soxr_delay_threshold: 30 milliseconds.
Jun 28 16:50:09 pi5 shairport-sync[302813]:          0.000669778 "shairport.c:255" "soxr" interpolation has been chosen.

This is my current config:

# shairport-sync --displayConfig
         0.000898019 "shairport.c:2126" >> Display Config Start.
         0.002854074 "shairport.c:2126" 
         0.000040685 "shairport.c:2126" From "uname -a":
         0.000004741 "shairport.c:2126"  Linux pi5 6.6.31+rpt-rpi-2712 #1 SMP PREEMPT Debian 1:6.6.31-1+rpt1 (2024-05-29) aarch64 GNU/Linux
         0.009215556 "shairport.c:2126" 
         0.000894629 "shairport.c:2126" From /etc/os-release:
         0.000060945 "shairport.c:2126"  Debian GNU/Linux 12 (bookworm)
         0.008882537 "shairport.c:2126" 
         0.003028240 "shairport.c:2126" From /sys/firmware/devicetree/base/model:
         0.000072649 "shairport.c:2126"  Raspberry Pi 5 Model B Rev 1.0
         0.000083944 "shairport.c:2126" 
         0.000029556 "shairport.c:2126" Shairport Sync Version String:
         0.000005796 "shairport.c:2126"  4.3.4-dev-15-g0412a840-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-jack-stdout-pipe-soxr-metadata-mqtt-dbus-sysconfdir:/etc
         0.000009000 "shairport.c:2126" 
         0.000002296 "shairport.c:2126" Command Line:
         0.000002926 "shairport.c:2126"  shairport-sync --displayConfig
         0.000024778 "shairport.c:2126" 
         0.000006074 "shairport.c:2126" Configuration File:
         0.000002555 "shairport.c:2126"  /etc/shairport-sync.conf
         0.000007315 "shairport.c:2126" 
         0.000116185 "shairport.c:2126" Configuration File Settings:
         0.000016315 "shairport.c:2126"  general : 
         0.000002648 "shairport.c:2126"  {
         0.000002500 "shairport.c:2126"    name = "Pi5";
         0.000003056 "shairport.c:2126"    output_backend = "alsa";
         0.000002685 "shairport.c:2126"    port = 7000;
         0.000002296 "shairport.c:2126"    airplay_device_id_offset = 2;
         0.000002389 "shairport.c:2126"    regtype = "_airplay._tcp";
         0.000003074 "shairport.c:2126"  };
         0.000002315 "shairport.c:2126"  sessioncontrol : 
         0.000002260 "shairport.c:2126"  {
         0.000001925 "shairport.c:2126"    run_this_before_play_begins = "/srv/http/command/airplay_toggle on";
         0.000006075 "shairport.c:2126"    run_this_after_play_ends = "/srv/http/command/airplay_toggle off";
         0.000003648 "shairport.c:2126"    wait_for_completion = "yes";
         0.000002870 "shairport.c:2126"  };
         0.000002667 "shairport.c:2126"  alsa : 
         0.000002352 "shairport.c:2126"  {
         0.000002166 "shairport.c:2126"    output_device = "sysdefault:CARD=vc4hdmi0";
         0.000003482 "shairport.c:2126"    mixer_control_name = "PCM";
         0.000002685 "shairport.c:2126"    mixer_device = "hw:CARD=vc4hdmi0";
         0.000004315 "shairport.c:2126"    output_rate = 44100;
         0.000005277 "shairport.c:2126"    output_format = "S16";
         0.000002963 "shairport.c:2126"  };
         0.000001834 "shairport.c:2126"  pw : 
         0.000002463 "shairport.c:2126"  {
         0.000002166 "shairport.c:2126"  };
         0.000003130 "shairport.c:2126"  pipe : 
         0.000001815 "shairport.c:2126"  {
         0.000002981 "shairport.c:2126"    name = "/tmp/shairport-sync-output-pipe";
         0.000004352 "shairport.c:2126"  };
         0.000002185 "shairport.c:2126"  metadata : 
         0.000002630 "shairport.c:2126"  {
         0.000002537 "shairport.c:2126"    enabled = "yes";
         0.000002852 "shairport.c:2126"    include_cover_art = "yes";
         0.000002315 "shairport.c:2126"    pipe_name = "/tmp/shairport-sync-metadata";
         0.000002500 "shairport.c:2126"  };
         0.000002611 "shairport.c:2126"  diagnostics : 
         0.000002148 "shairport.c:2126"  {
         0.000002222 "shairport.c:2126"    log_verbosity = 2;
         0.000002796 "shairport.c:2126"  };
         0.000003778 "shairport.c:2126" 
         0.000002500 "shairport.c:2126" >> Display Config End.
         0.000003630 "shairport.c:2128" >> Goodbye!
         0.000014204 "shairport.c:1588" exit function called...

The phone is 192.168.2.16. When I am trying to play from the phone. I see it try to connect but then it disconnects and does not play.

I tried to connect it to OwnTone as well and did not get even this far. OwnTone will not even try to connect to it. When I try, the shairport-sync log shows something to the effect of 'this is a ntp stream and it can only understand ptp'. In a discussion with the dev of owntone, he mentioned that owntone, and possibly AirPlay2, require ntp synchronization versus the ptp of AirPlay1. I do not know what that means, exactly...

If there is more logging or things I can try, please let me know.

mikebrady commented 1 day ago

Thanks. There is a line:

Jun 28 16:50:07 pi5 shairport-sync[302252]:          0.372095685 "shairport.c:1750" exit on SIGTERM

which indicates that Shairport Sync is receiving a SIGTERM -- something seems to trying to terminate it. Any idea what that could be? Do you have a script that terminates or restarts Shairport Sync anywhere? What do those airplay_toggle on and airplay_toggle offcommands do?

gearhead commented 1 day ago

Mike,

We are looking into it. The toggle is supposed to turn off mpd to make sure only one process is trying to use alsa and display a message in the ui, not restart the service. We will dig through the rest of our code and see if there is something we are doing to restart it. I do know we restart it periodically but we are not supposed to do it when playing a stream...

gearhead commented 13 hours ago

Mike, It seems a bit flaky. Probably with our end. I tried it again this morning and it restarted. I tried it again and it played. I will assume the problem is on our end and not with with shairport-sync as it works for you and I was able to get 2 implementations working here w/o issue this morning. Was able to connect from one iPhone to both sinks individually and simultaneously while playing form YouTube Music on the iPhone.

On a similar note, I assume you know that shairport-sync, when set up as an AirPlay 2 sink, will not accept a connection from owntone I just played from my iPhone, so it was 'just working'. I then tried to select the output in owntone.

On the RPi running owntone, I get this:

Jun 30 10:11:55 kitchenrune owntone[112028]: [2024-06-30 10:11:55] [  LOG]   player: The AirPlay 2 device 'Pi5' failed to activate
Jun 30 10:11:55 kitchenrune owntone[112028]: [2024-06-30 10:11:55] [  LOG]      web: JSON api request failed with error code 500 (/api/outputs/237747341274684)

On the RPi running shairport-sync, the sink, I get:

Jun 30 10:11:55 pi5 shairport-sync[2262533]:         12.657059992 "rtsp.c:5733" Connection 5: New connection from 192.168.2.200:45464 to self at 192.168.2.201:7000.
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.034423130 "rtsp.c:2290" Connection 5: handle_pair-setup Content-Length 9
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.170074889 "rtsp.c:2290" Connection 5: handle_pair-setup Content-Length 457
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.015500814 "rtsp.c:2911" Connection 5: SETUP (AirPlay 2)
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.000059352 "rtsp.c:2931" Connection 5 SETUP: No "streams" array has been found -- create an event thread and open a TCP port.
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.000011000 "rtsp.c:2950" Connection 5: SETUP: NTP setup from 192.168.2.200:45464 ("<unknown>") to self at 192.168.2.201:7000.
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.000004185 "rtsp.c:3194" SETUP on Connection 5: ntp stream handling is not implemented!
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.000004963 "rtsp.c:3196" *warning: Shairport Sync can not handle NTP streams.
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.002658389 "rtsp.c:1335" Connection 5: Connection closed by client.
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.000029093 "rtsp.c:5116" Connection 5: NTP stream rtsp_conversation_thread_func_cleanup_function called.
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.000007518 "rtsp.c:2706" Connection 5: TEARDOWN NTP stream connection.
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.000005389 "rtsp.c:2773" Connection 5: TEARDOWN NTP stream -- close the connection complete
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.000003741 "rtsp.c:5148" Connection 5: terminating -- closing RTSP connection socket 13: from 192.168.2.200:45464 to self at 192.168.2.201:7000.
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.000216000 "rtsp.c:5215" Connection 5: Closed.
Jun 30 10:11:55 pi5 shairport-sync[2262533]:          0.000018407 "rtsp.c:5437" Connection 5: RTSP thread exit.

Keith