search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.3k stars 574 forks source link

[Problem]: ALSA output not closed after Airplay 2 client disconnects #1546

Closed moodeaudio closed 2 years ago

moodeaudio commented 2 years ago

What happened?

Testing Airplay 2

  1. Use iPhone to check "Moode Airplay" a pi running shairport-sync and then play something
  2. Uncheck "Moode Airplay"
  3. After some seconds shairport-sync performs run_this_after_exiting_active_state which runs a script that changes the moOde UI, This works as expected.

What happened.

The ALSA output remained open

pi@moode:~ $ cat /proc/asound/card0/pcm0p/sub0/hw_params
access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (705600/16)
period_size: 256
buffer_size: 131072

What was expected

The ALSA output would be closed (restarting shairport-sync did close the output)

pi@moode:~ $ cat /proc/asound/card0/pcm0p/sub0/hw_params
closed

Some settings and the launch string

disable_standby_mode = "auto"

/usr/bin/shairport-sync -vvu -a "Moode Airplay" -- -d _audioout > /var/log/shairport-sync.log 2>&1 &

Relevant log output

pi@moode:~ $ tail -f /var/log/shairport-sync.log 
         0.000040938 "dbus-service.c:400" >> start including delta time in logs
         0.000067344 "dbus-service.c:413" >> start including file and line in logs
         0.000092031 "dbus-service.c:1087" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
         0.001054114 "mpris-service.c:341" MPRIS service started at "org.mpris.MediaPlayer2.ShairportSync" on the system bus.
         0.006719063 "mdns_avahi.c:220" avahi: service 'B827EB90BE5B@Moode Airplay' group is not yet committed.
         0.004673333 "mdns_avahi.c:268" avahi: avahi_entry_group_commit 0
         0.000350938 "mdns_avahi.c:463" avahi_dacp_monitor_start Avahi DACP monitor successfully started
         0.000418802 "mdns_avahi.c:224" avahi: service 'B827EB90BE5B@Moode Airplay' group is registering.
         0.913344531 "mdns_avahi.c:191" avahi: service 'B827EB90BE5B@Moode Airplay' successfully added.
         0.556606406 "shairport.c:242" soxr_delay: 7457634 nanoseconds, soxr_delay_threshold: 30 milliseconds.
       126.937609899 "rtsp.c:5463" Connection 1: New connection from fe80::1852:9899:837d:e8f6:52334 to self at fe80::c3af:fe48:7233:46fc:7000.
         0.002231823 "rtsp.c:2015" Connection 1: GET /info :: Content-Length 70
         0.000149896 "rtsp.c:2017" GET request
         0.000029010 "rtsp.c:2017"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000027761 "rtsp.c:2017"   Type: "Content-Length", content: "70"
         0.000032031 "rtsp.c:2017"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000025573 "rtsp.c:2017"   Type: "CSeq", content: "0"
         0.000025000 "rtsp.c:2017"   Type: "DACP-ID", content: "373E578048A40DD4"
         0.000025000 "rtsp.c:2017"   Type: "Active-Remote", content: "190682389"
         0.000024635 "rtsp.c:2017"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000071719 "rtsp.c:2017"   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.000032761 "rtsp.c:1675" GET /info:
         0.000026979 "rtsp.c:1675"   Type: "X-Apple-ProtocolVersion", content: "1"
         0.000025104 "rtsp.c:1675"   Type: "Content-Length", content: "70"
         0.000024948 "rtsp.c:1675"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000024844 "rtsp.c:1675"   Type: "CSeq", content: "0"
         0.000024479 "rtsp.c:1675"   Type: "DACP-ID", content: "373E578048A40DD4"
         0.000025052 "rtsp.c:1675"   Type: "Active-Remote", content: "190682389"
         0.000024844 "rtsp.c:1675"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000056979 "rtsp.c:1675"   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.000030000 "rtsp.c:1684" Connection 1: GET_INFO: Source AirPlay Version is: 620.8.2.
         0.000042291 "rtsp.c:1707" GET /info Stage 1: qualifier: txtAirPlay
         0.000784740 "rtsp.c:1789" GET /info Stage 1 Response:
         0.000141667 "rtsp.c:1789"   Response Code: 501.
         0.000029010 "rtsp.c:1789"   Type: "CSeq", content: "0"
         0.000032500 "rtsp.c:1789"   Type: "Server", content: "AirTunes/366.0"
         0.000025521 "rtsp.c:1789"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000180312 "rtsp.c:1789"   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>
        BWFjbD0wGmRldmljZWlkPWI4OjI3OmViOjkwOmJlOjViG2ZlYXR1cmVzPTB4NDA1RkNB
        MDAsMHgxQzM0MAdyc2Y9MHgwCWZsYWdzPTB4NBRtb2RlbD1TaGFpcnBvcnQgU3luYw1t
        YW51ZmFjdHVyZXI9DXNlcmlhbE51bWJlcj0NcHJvdG92ZXJzPTEuMQ1zcmN2ZXJzPTM2
        Ni4wJ3BpPWI1ZTM5M2UzLTYyNmYtNGMxMS05NmI1LTE2ODQ5OWI4NWNjMChnaWQ9YjVl
        MzkzZTMtNjI2Zi00YzExLTk2YjUtMTY4NDk5Yjg1Y2MwBmdjZ2w9MENwaz1kYzJhZDkw
        OWI1YWI1NGU0ZmNlZGNhMWUyYTI2ZTY3NDhmNDAzYzI0ODNkMzEyN2VlN2Y2ODAwNGEz
        NDE4ZGZj
        </data>
        <key>features</key>
        <integer>496155702053376</integer>
        <key>deviceID</key>
        <string>b8:27:eb:90:be:5b</string>
        <key>pi</key>
        <string>b5e393e3-626f-4c11-96b5-168499b85cc0</string>
        <key>name</key>
        <string>Moode Airplay</string>
        <key>model</key>
        <string>Shairport Sync</string>
</dict>
</plist>
--
         0.000059167 "rtsp.c:1536" Responding with content of length 911
         0.010921615 "rtsp.c:2175" Connection 1: pair-verify Content-Length 37
         0.001387343 "rtsp.c:2211" pair-verify response
         0.000072709 "rtsp.c:2211"   Response Code: 200.
         0.000028281 "rtsp.c:2211"   Type: "CSeq", content: "1"
         0.000026042 "rtsp.c:2211"   Type: "Server", content: "AirTunes/366.0"
         0.000025573 "rtsp.c:2211"   Type: "Content-Type", content: "application/octet-stream"
         0.000026197 "rtsp.c:2211"   No Content Plist. Content length: 140.
         0.000031875 "rtsp.c:1536" Responding with content of length 140
         0.012197865 "rtsp.c:2219" Connection 1: pair-setup Content-Length 9
         0.017757917 "rtsp.c:2257" pair-setup response
         0.000095312 "rtsp.c:2257"   Response Code: 200.
         0.000029688 "rtsp.c:2257"   Type: "CSeq", content: "2"
         0.000026093 "rtsp.c:2257"   Type: "Server", content: "AirTunes/366.0"
         0.000025209 "rtsp.c:2257"   Type: "Content-Type", content: "application/octet-stream"
         0.000025885 "rtsp.c:2257"   No Content Plist. Content length: 409.
         0.000032552 "rtsp.c:1536" Responding with content of length 409
         0.034914844 "rtsp.c:2219" Connection 1: pair-setup Content-Length 457
         0.021357135 "rtsp.c:2257" pair-setup response
         0.000082761 "rtsp.c:2257"   Response Code: 200.
         0.000031562 "rtsp.c:2257"   Type: "CSeq", content: "3"
         0.000075886 "rtsp.c:2257"   Type: "Server", content: "AirTunes/366.0"
         0.000026302 "rtsp.c:2257"   Type: "Content-Type", content: "application/octet-stream"
         0.000026562 "rtsp.c:2257"   No Content Plist. Content length: 69.
         0.000031563 "rtsp.c:1536" Responding with content of length 69
         0.005819323 "rtsp.c:1536" Responding with content of length 142
         0.006608698 "rtsp.c:1536" Responding with content of length 32
         0.006688750 "rtsp.c:2827" Connection 1: SETUP (AirPlay 2)
         0.000152343 "rtsp.c:2838" Connection 1 SETUP: No "streams" array has been found -- create an event thread and open a TCP port.
         0.000035782 "rtsp.c:2850" Connection 1: AP2 PTP connection from fe80::1852:9899:837d:e8f6:52334 to self at fe80::c3af:fe48:7233:46fc:7000.
         0.000416302 "rtsp.c:557" Connection 1: request play lock.
         0.000060104 "rtsp.c:624" Connection 1: Got player lock.
         0.000191927 "metadata_hub.c:542" MH Client IP set to: "fe80::1852:9899:837d:e8f6"
         0.000249167 "dbus-service.c:195" Build metadata
         0.000236614 "ptp-utilities.c:116" ptp_shm_interface_open with mapped_addr = 548052770816
         0.000161146 "mpris-service.c:167" Build metadata
         0.000176354 "ptp-utilities.c:151" ptp_shm_interface_open -- already open!
         0.000053854 "rtsp.c:2902" SETUP "PTP" message
         0.000027084 "rtsp.c:2902"   Type: "Content-Length", content: "792"
         0.000025625 "rtsp.c:2902"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000025573 "rtsp.c:2902"   Type: "CSeq", content: "6"
         0.000024948 "rtsp.c:2902"   Type: "DACP-ID", content: "373E578048A40DD4"
         0.000048906 "metadata_hub.c:559" MH Server IP set to: "fe80::c3af:fe48:7233:46fc"
         0.000123125 "dbus-service.c:195" Build metadata
         0.000102188 "mpris-service.c:167" Build metadata
         0.000025208 "rtsp.c:2902"   Type: "Active-Remote", content: "190682389"
         0.000108333 "rtsp.c:2902"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000250885 "rtsp.c:2902"   Content Plist (as XML):

.
.
.

         0.000399896 "rtsp.c:2709" Connection 1: TEARDOWN PTP stream Close the stream.
         0.005997656 "player.c:1750" Cancelling AP2 timing, control and audio threads...
         0.000168698 "player.c:1753" Connection 1: Delete Realtime Audio Stream thread
         0.000933021 "rtp.c:1889" Realtime Audio Receiver Cleanup Start.
         0.000206666 "rtp.c:1892" Connection 49385: closing realtime audio port 0
         0.000056927 "rtp.c:1894" Realtime Audio Receiver Cleanup Done.
         0.000365938 "player.c:1767" Connection 31: Delete AirPlay 2 Control thread
         0.000686823 "rtp.c:1636" Connection 1: AP2 Control Receiver Cleanup.
         0.000164219 "rtp.c:1638" Connection 1: UDP control port 43580 closed.
         0.000657656 "rtp.c:1325" Connection 1: Clear anchor information.
         0.000720417 "player.c:1822" Connection 1: player terminated.
         0.002931875 "player.c:3487" pend
         0.000303437 "rtsp.c:2714" Connection 1: TEARDOWN PTP stream Close the stream complete
         0.000801302 "dbus-service.c:195" Build metadata
         0.001416250 "mpris-service.c:167" Build metadata
         0.038896875 "rtsp.c:2698" TEARDOWN: 
         0.000173073 "rtsp.c:2698"   Type: "Content-Length", content: "42"
         0.000051406 "rtsp.c:2698"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000047604 "rtsp.c:2698"   Type: "CSeq", content: "28"
         0.000112292 "rtsp.c:2698"   Type: "DACP-ID", content: "373E578048A40DD4"
         0.000098698 "rtsp.c:2698"   Type: "Active-Remote", content: "190682389"
         0.000061042 "rtsp.c:2698"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000071875 "rtsp.c:2698"   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/>
</plist>
--
         0.000055573 "rtsp.c:2717" Connection 1: TEARDOWN PTP stream Close the connection.
         0.000048489 "rtsp.c:2635" Connection 1: TEARDOWN PTP stream connection.
         0.000044427 "rtsp.c:2655" Connection 1: TEARDOWN PTP stream Delete Event Thread.
         0.000649636 "rtp.c:1567" Connection 1: AP2 Event Receiver Cleanup.
         0.000926614 "rtsp.c:2663" Connection 1: TEARDOWN PTP stream Close Event Socket.
         0.001522084 "rtsp.c:2683" Connection 1: TEARDOWN mdns_update on PTP stream.
         0.003048073 "rtsp.c:540" Connection 1: release play lock.
         0.000492656 "rtsp.c:546" Connection 1: play lock released.
         0.000096094 "ptp-utilities.c:176" Send control message to NQPTP: "/nqptp T"
         0.000811041 "rtsp.c:2721" Connection 1: TEARDOWN PTP stream Close the connection complete
         0.009558073 "rtsp.c:1344" Connection 1: Closed by client: from fe80::1852:9899:837d:e8f6:52334 to self at fe80::c3af:fe48:7233:46fc:7000.
         0.000161146 "rtsp.c:4927" Connection 1: rtsp_conversation_thread_func_cleanup_function called.
         0.000054167 "rtsp.c:2635" Connection 1: TEARDOWN PTP stream connection.
         0.000403333 "rtsp.c:2683" Connection 1: TEARDOWN mdns_update on PTP stream.
         0.003431354 "rtsp.c:540" Connection 1: release play lock.
         0.000490469 "ptp-utilities.c:176" Send control message to NQPTP: "/nqptp T"
         0.001302604 "rtsp.c:5017" Connection 1: Closed.
         1.279490729 "mdns_avahi.c:160" (Browser) REMOVE: service 'iTunes_Ctrl_373E578048A40DD4' of type '_dacp._tcp' in domain 'local'.
         0.000152083 "dacp.c:466" dacp_monitor_port_update_callback with Remote ID "373E578048A40DD4", target ID "373E578048A40DD4" and port number 0.
         0.000171771 "mdns_avahi.c:160" (Browser) REMOVE: service 'iTunes_Ctrl_373E578048A40DD4' of type '_dacp._tcp' in domain 'local'.
         0.000040104 "dacp.c:466" dacp_monitor_port_update_callback with Remote ID "373E578048A40DD4", target ID "373E578048A40DD4" and port number 0.
         0.684306823 "dbus-service.c:195" Build metadata
         0.000884791 "mpris-service.c:167" Build metadata
         7.973871872 "activity_monitor.c:88" aend
         0.001301354 "dbus-service.c:195" Build metadata
         0.001025625 "mpris-service.c:167" Build metadata
         0.000852865 "dbus-service.c:460" >> deactivating disable standby
         0.000310156 "activity_monitor.c:171" am_state: am_inactive
         0.000610417 "audio_alsa.c:2067" keep_dac_busy is now "no"
        34.675605143 "rtsp.c:752" Connection 1: deleted in cleanup.
         0.000370156 "rtsp.c:752" Connection 2: deleted in cleanup.
^C
pi@moode:~ $

Operating System?

pi@moode:~ $ uname -a Linux moode 5.15.61-v8+ #1579 SMP PREEMPT Fri Aug 26 11:16:44 BST 2022 aarch64 GNU/Linux

Version?

pi@moode:~ $ shairport-sync -V 4.1-dev-556-g1d6a378c-AirPlay2-libdaemon-OpenSSL-Avahi-ALSA-jack-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc

How did you install Shairport Sync?

Built from source

Check previous issues

mikebrady commented 2 years ago

Thanks for the report!

mikebrady commented 2 years ago

Hello again, Tim. That was indeed a bug -- many thanks!

I think it is fixed in the latest push to the development branch. The time given to the DAC hardware to fully stop has also been extended from five to 10 milliseconds before fully releasing the device descriptors.

moodeaudio commented 2 years ago

Nice :-)

I'll try to test this weekend.

moodeaudio commented 2 years ago

Works perfectly now. Bug has been fixed :-)

mikebrady commented 2 years ago

Hi Tim. A possibly related further issue is that when an AirPlay 2 buffered stream was paused or stopped and disable_standby_mode was "off", the output DAC was left open until the AirPlay 2 was taken down or timed out after about 6 minutes.

That has been changed -- the DAC will now be closed immediately when a buffered stream pause message is received and disable_standby_mode is "off".

moodeaudio commented 2 years ago

Thanks Mike.