search

mikebrady / shairport-sync

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

Crash on older MacBook #1281

Closed mxkyb closed 3 years ago

mxkyb commented 3 years ago

Steps to reproduce

Compile from development branch on Raspberry Pi.

Run shairport-sync on Raspberry Pi.

Change system output on MacBook to airplay. Start playing sound. Shairport-sync app will crash (see logs below).

Same setup of shairport-sync will work perfectly on newer versions of macOS and iOS.

Hardware Info

$ shairport-sync -V
4.0-dev-312-g687fd167-AirPlay2-OpenSSL-Avahi-ALSA-soxr-metadata-dbus-sysconfdir:/etc

$ uname -r
5.10.52-v7l+

$ cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

Shairport-sync Logs

$ shairport-sync -vu --statistics
         0.001321607 "shairport.c:1823" Started!
         0.000121888 "shairport.c:1826" Started in Airplay 2 mode!
         0.000073463 "shairport.c:1868" software version: "4.0-dev-312-g687fd167-AirPlay2-OpenSSL-Avahi-ALSA-soxr-metadata-dbus-sysconfdir:/etc"
         0.000043352 "shairport.c:1874" log verbosity is 1.
         0.000082499 "audio_alsa.c:1015" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000065352 "audio_alsa.c:1302" alsa: disable_standby_mode is "never".
         0.000041796 "audio_alsa.c:1304" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000041185 "audio_alsa.c:1306" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000066500 "audio_alsa.c:1345" alsa: output device name is "hw:sndrpihifiberry".
         0.000251499 "shairport.c:1903" libsodium initialised.
         0.000052092 "shairport.c:1930" disable resend requests is off.
         0.000040834 "shairport.c:1934" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000041425 "shairport.c:1935" statistics_requester status is 1.
         0.000039371 "shairport.c:1940" rtsp listening port is 7000.
         0.000040259 "shairport.c:1941" udp base port is 6001.
         0.000038722 "shairport.c:1942" udp port range is 10.
         0.000042925 "shairport.c:1943" player name is "Wohnzimmer".
         0.000039315 "shairport.c:1944" backend is "alsa".
         0.000039056 "shairport.c:1945" run_this_before_play_begins action is "(null)".
         0.000039296 "shairport.c:1946" run_this_after_play_ends action is "(null)".
         0.000042592 "shairport.c:1947" wait-cmd status is 0.
         0.000039593 "shairport.c:1948" run_this_before_play_begins may return output is 0.
         0.000039944 "shairport.c:1949" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000039352 "shairport.c:1950" run_this_before_entering_active_state action is  "(null)".
         0.000042740 "shairport.c:1951" run_this_after_exiting_active_state action is  "(null)".
         0.000040630 "shairport.c:1952" active_state_timeout is  10.000000 seconds.
         0.000041629 "shairport.c:1953" mdns backend "(null)".
         0.000042519 "shairport.c:1957" interpolation setting is "auto".
         0.000042055 "shairport.c:1958" interpolation soxr_delay_threshold is 30.
         0.000039074 "shairport.c:1959" resync time is 0.050000 seconds.
         0.000042889 "shairport.c:1960" allow a session to be interrupted: 0.
         0.000038814 "shairport.c:1961" busy timeout time is 0.
         0.000038667 "shairport.c:1962" drift tolerance is 0.001995 seconds.
         0.000034963 "shairport.c:1963" password is "(null)".
         0.000016666 "shairport.c:1964" ignore_volume_control is 0.
         0.000026074 "shairport.c:1968" volume_max_db is not set
         0.000042333 "shairport.c:1970" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000040222 "shairport.c:1974" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000039648 "shairport.c:1976" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000035223 "shairport.c:1977" disable_synchronization is 0.
         0.000016518 "shairport.c:1978" use_mmap_if_available is 1.
         0.000015500 "shairport.c:1980" output_format automatic selection is enabled.
         0.000015759 "shairport.c:1984" output_rate automatic selection is enabled.
         0.000015445 "shairport.c:1988" audio backend desired buffer length is 0.200000 seconds.
         0.000016351 "shairport.c:1990" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000049945 "shairport.c:1991" audio backend latency offset is 0.000000 seconds.
         0.000040666 "shairport.c:1993" audio backend silence lead-in time is "auto".
         0.000038944 "shairport.c:1997" zeroconf regtype is "_raop._tcp".
         0.000042574 "shairport.c:1998" decoders_supported field is 1.
         0.000039093 "shairport.c:1999" use_apple_decoder is 0.
         0.000038722 "shairport.c:2000" alsa_use_hardware_mute is 0.
         0.000038870 "shairport.c:2004" no special mdns service interface was requested.
         0.000060204 "shairport.c:2008" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000046611 "shairport.c:2014" metadata enabled is 1.
         0.000039777 "shairport.c:2015" metadata pipename is "/tmp/shairport-sync-metadata".
         0.000040556 "shairport.c:2017" metadata socket address is "(null)" port 0.
         0.000042370 "shairport.c:2018" metadata socket packet size is "500".
         0.000039407 "shairport.c:2019" get-coverart is 1.
         0.000038907 "shairport.c:2037" loudness is 0.
         0.000041648 "shairport.c:2038" loudness reference level is -20.000000
         0.000153111 "rtsp.c:3194" metadata pipe name is "/tmp/shairport-sync-metadata".
         0.007128622 "dbus-service.c:1054" *warning: could not acquire a Shairport Sync native D-Bus interface "org.gnome.ShairportSync.i1098" on the system bus.
         1.493785152 "shairport.c:212" "soxr" interpolation has been chosen.
         8.728374101 "rtsp.c:2250" Connection 1. Realtime Audio Stream Detected.
         0.041806960 "audio_alsa.c:529" alsa: output format chosen is "S32".
         0.000126888 "audio_alsa.c:569" alsa: output speed chosen is 44100.
         0.116208302 "rtp.c:1322" Connection 1: Clock 49d705e4b5530000 is now the new anchor clock and master clock. History: 195022.782118 milliseconds.
         0.000137740 "rtp.c:1404" Connection 1: NQPTP new master clock 49d705e4b5530000.
Segmentation fault
mikebrady commented 3 years ago

Thanks for the very interesting post. We don't have an older machine to hand just now, but it would be great if you could run Shairport Sync in the gdb debugger and run a backtrace at the point of the Segmentation fault. Would that be possible? We could give a few (simple) instructions if necessary...

mxkyb commented 3 years ago

Here is what I tried. If you need more info or something different please let me know – but then I'll probably need some instructions :)

$ gdb ./shairport-sync
GNU gdb (Raspbian 8.2.1-2) 8.2.1
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "arm-linux-gnueabihf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./shairport-sync...done.
(gdb) run
Starting program: /home/pi/shairport-sync/shairport-sync/shairport-sync
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
[New Thread 0xb0379aa0 (LWP 1952)]
[New Thread 0xafb78aa0 (LWP 1953)]
[New Thread 0xaf377aa0 (LWP 1954)]
[New Thread 0xae9feaa0 (LWP 1955)]
[New Thread 0xae1fdaa0 (LWP 1956)]
[New Thread 0xad5feaa0 (LWP 1957)]
[New Thread 0xacdfdaa0 (LWP 1958)]
[New Thread 0xac1feaa0 (LWP 1959)]
[New Thread 0xab9fdaa0 (LWP 1960)]
[New Thread 0xab1fcaa0 (LWP 1961)]
[New Thread 0xaa9fbaa0 (LWP 1962)]
[New Thread 0xaa1faaa0 (LWP 1963)]
[New Thread 0xa99f9aa0 (LWP 1964)]
[Thread 0xafb78aa0 (LWP 1953) exited]
[New Thread 0xa91f8aa0 (LWP 1965)]
[New Thread 0xa89f7aa0 (LWP 1966)]
[New Thread 0xa81f6aa0 (LWP 1967)]
[New Thread 0xa79f5aa0 (LWP 1968)]
[New Thread 0xa71f4aa0 (LWP 1969)]
[New Thread 0xa68efaa0 (LWP 1970)]

Thread 19 "shairport-sync" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0xa71f4aa0 (LWP 1969)]
0xb58302d0 in ?? () from /lib/arm-linux-gnueabihf/libsodium.so.23
(gdb) backtrace
Python Exception <class 'gdb.MemoryError'> Cannot access memory at address 0x5a8aa454:
#0  0xb58302d0 in ?? () from /lib/arm-linux-gnueabihf/libsodium.so.23
Cannot access memory at address 0x5a8aa454
$ sudo gdb ./shairport-sync
GNU gdb (Raspbian 8.2.1-2) 8.2.1
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "arm-linux-gnueabihf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./shairport-sync...done.
(gdb) run
Starting program: /home/pi/shairport-sync/shairport-sync/shairport-sync
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
[New Thread 0xb0379aa0 (LWP 1978)]
[New Thread 0xafb78aa0 (LWP 1979)]
[New Thread 0xaf377aa0 (LWP 1980)]
[New Thread 0xae9feaa0 (LWP 1981)]
[New Thread 0xadffeaa0 (LWP 1982)]
[New Thread 0xad5feaa0 (LWP 1983)]
[New Thread 0xacbfeaa0 (LWP 1984)]
[New Thread 0xabffeaa0 (LWP 1985)]
[New Thread 0xab7fdaa0 (LWP 1986)]
[New Thread 0xaaffcaa0 (LWP 1987)]
[New Thread 0xaa7fbaa0 (LWP 1988)]
[New Thread 0xa9ffaaa0 (LWP 1989)]
[New Thread 0xa97f9aa0 (LWP 1990)]
[Thread 0xafb78aa0 (LWP 1979) exited]
[New Thread 0xa8ff8aa0 (LWP 1991)]
[New Thread 0xa87f7aa0 (LWP 1992)]
[New Thread 0xa7ff6aa0 (LWP 1993)]
[New Thread 0xa77f5aa0 (LWP 1994)]
[New Thread 0xa6ff4aa0 (LWP 1995)]
[New Thread 0xa67f3aa0 (LWP 1996)]

Thread 20 "shairport-sync" received signal SIG32, Real-time event 32.
[Switching to Thread 0xa67f3aa0 (LWP 1996)]
futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0xa67f2f80, expected=0, futex_word=0xac10f640)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
205 ../sysdeps/unix/sysv/linux/futex-internal.h: No such file or directory.
(gdb) backtrace
#0  0xb509257c in futex_abstimed_wait_cancelable
    (private=<optimized out>, abstime=0xa67f2f80, expected=0, futex_word=0xac10f640)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  0xb509257c in __pthread_cond_wait_common (abstime=0xa67f2f80, mutex=0x0, cond=0xac10f618)
    at pthread_cond_wait.c:539
#2  0xb509257c in __pthread_cond_timedwait (cond=0xac10f618, cond@entry=0xa290, mutex=0x0,
    mutex@entry=0x2ed30 <buffer_get_frame_cleanup_handler>, abstime=0xa67f2f80, abstime@entry=0xa67f2f78)
    at pthread_cond_wait.c:667
#3  0x000335b0 in buffer_get_frame (conn=0x0, conn@entry=0xac105388) at player.c:1307
#4  0x00034d60 in player_thread_func (arg=<optimized out>) at player.c:2060
#5  0xb508b494 in start_thread (arg=0xa67f3aa0) at pthread_create.c:486
#6  0xb4e01578 in  () at ../sysdeps/unix/sysv/linux/arm/clone.S:73
mikebrady commented 3 years ago

Great stuff, thanks. Could you see if anything more can be gained with:

(gdb) bt full

(Or maybe bt all — I can’t check right now.)

mikebrady commented 3 years ago

Looking at the log more carefully, gdb is stopping only because a (benign) SIG32 signal was received. To continue program execution, enter:

(gdb) handle SIG32 nostop

...and continue.

(gdb) cont

And it's (gdb) bt full. Many thanks for your help so far.

mxkyb commented 3 years ago

Well, thank you for your great work :)

This is what I got:

$ sudo gdb ./shairport-sync
GNU gdb (Raspbian 8.2.1-2) 8.2.1
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "arm-linux-gnueabihf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./shairport-sync...done.
(gdb) run
Starting program: /home/pi/shairport-sync/shairport-sync/shairport-sync
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
[New Thread 0xb0379aa0 (LWP 2810)]
[New Thread 0xafb78aa0 (LWP 2811)]
[New Thread 0xaf377aa0 (LWP 2812)]
[New Thread 0xae9feaa0 (LWP 2813)]
[New Thread 0xadffeaa0 (LWP 2814)]
[New Thread 0xad5feaa0 (LWP 2815)]
[New Thread 0xacbfeaa0 (LWP 2816)]
[New Thread 0xabffeaa0 (LWP 2817)]
[New Thread 0xab7fdaa0 (LWP 2818)]
[New Thread 0xaaffcaa0 (LWP 2819)]
[New Thread 0xaa7fbaa0 (LWP 2820)]
[New Thread 0xa9ffaaa0 (LWP 2821)]
[New Thread 0xa97f9aa0 (LWP 2822)]
[Thread 0xafb78aa0 (LWP 2811) exited]
[New Thread 0xa8ff8aa0 (LWP 2823)]
[New Thread 0xa87f7aa0 (LWP 2824)]
[New Thread 0xa7ff6aa0 (LWP 2825)]
[New Thread 0xa77f5aa0 (LWP 2826)]
[New Thread 0xa6ff4aa0 (LWP 2827)]
[New Thread 0xa67f3aa0 (LWP 2828)]

Thread 20 "shairport-sync" received signal SIG32, Real-time event 32.
[Switching to Thread 0xa67f3aa0 (LWP 2828)]
futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0xa67f2f80, expected=0, futex_word=0xc7108)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
205 ../sysdeps/unix/sysv/linux/futex-internal.h: No such file or directory.
(gdb) handle SIG32 nostop
Signal        Stop  Print   Pass to program Description
SIG32         No    Yes Yes     Real-time event 32
(gdb) cont
Continuing.
[Thread 0xab7fdaa0 (LWP 2818) exited]

Thread 19 "shairport-sync" received signal SIG32, Real-time event 32.
[Thread 0xa6ff4aa0 (LWP 2827) exited]

Thread 18 "shairport-sync" received signal SIG32, Real-time event 32.
[Thread 0xa77f5aa0 (LWP 2826) exited]
[Thread 0xa67f3aa0 (LWP 2828) exited]
[New Thread 0xa67f3aa0 (LWP 2830)]
[New Thread 0xa77f5aa0 (LWP 2831)]
[New Thread 0xa6ff4aa0 (LWP 2832)]

Thread 22 "shairport-sync" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0xa77f5aa0 (LWP 2831)]
0xb58302d0 in ?? () from /lib/arm-linux-gnueabihf/libsodium.so.23
(gdb) bt full
#0  0xb58302d0 in  () at /lib/arm-linux-gnueabihf/libsodium.so.23
#1  0xb580b3ac in crypto_aead_chacha20poly1305_ietf_decrypt_detached ()
    at /lib/arm-linux-gnueabihf/libsodium.so.23
#2  0xfffffffe in  ()
mikebrady commented 3 years ago

Thanks. That was exactly what I meant. Unfortunately, it's not producing much of value. But there is one more thing that you could try, if you would be kind enough. The idea is to compile Shairport Sync with all optimisations turned off, so that the backtrace can have the best chance to provide as much information as possible. To turn off optimisations, add the following preamble to your ./configure... command: CFLAGS="-O0 -g" CXXFLAGS="-O0 -g".

For example, you might have a /.configure... step like this:

$ CFLAGS="-O0 -g" CXXFLAGS="-O0 -g" ./configure --sysconfdir=/etc --with-alsa --with-soxr --with-avahi --with-ssl=openssl --with-systemd

Then do a:

$ make clean all -j

The clean is needed to remove the existing (optimised) object files before calculating what needs to be built.

mxkyb commented 3 years ago

I fear it doesn't include new information:

Compiled with:

$ CFLAGS="-O0 -g" CXXFLAGS="-O0 -g" ./configure --sysconfdir=/etc --with-alsa --with-soxr --with-avahi --with-ssl=openssl --with-systemd --with-dbus-interface --with-airplay-2
(gdb) cont
Continuing.

Thread 19 "shairport-sync" received signal SIG32, Real-time event 32.
[Thread 0xa77f5aa0 (LWP 13030) exited]

Thread 18 "shairport-sync" received signal SIG32, Real-time event 32.
[Thread 0xa7ff6aa0 (LWP 13029) exited]
[Thread 0xa6ff4aa0 (LWP 13031) exited]

Thread 17 "shairport-sync" received signal SIG32, Real-time event 32.
[Thread 0xa87f7aa0 (LWP 13028) exited]

Thread 16 "shairport-sync" received signal SIG32, Real-time event 32.
[Thread 0xa8ff8aa0 (LWP 13027) exited]
[Thread 0xab7fdaa0 (LWP 13026) exited]
[New Thread 0xab7fdaa0 (LWP 13059)]
[New Thread 0xa8ff8aa0 (LWP 13060)]
[New Thread 0xa87f7aa0 (LWP 13061)]
[New Thread 0xa6ff4aa0 (LWP 13062)]
[New Thread 0xa7ff6aa0 (LWP 13063)]
[New Thread 0xa77f5aa0 (LWP 13064)]

Thread 25 "shairport-sync" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0xa7ff6aa0 (LWP 13063)]
0xb58302d0 in ?? () from /lib/arm-linux-gnueabihf/libsodium.so.23
(gdb) bt full
#0  0xb58302d0 in  () at /lib/arm-linux-gnueabihf/libsodium.so.23
#1  0xb580b3ac in crypto_aead_chacha20poly1305_ietf_decrypt_detached () at /lib/arm-linux-gnueabihf/libsodium.so.23
#2  0xfffffffe in  ()
mxkyb commented 3 years ago

If there is anything else I can do I am happy to try

edit: A difference to your command I just noticed, I added --with-airplay-2.

mikebrady commented 3 years ago

Thanks again. We'll try some other way -- maybe 10.14 running in a VM.

mikebrady commented 3 years ago

Well, I managed to replicate it running 10.14.6 in a VMware Fusion VM and following your instructions. Thanks!

mikebrady commented 3 years ago

Well, that is interesting. It turns out that when you direct the Sound Output to AirPlay 2 from macOS 10.14.6 (Mojave), it uses a version of the AirPlay 2 protocol that is different from the current one, and it is missing an important parameter, a "shk", possibly a session key. When playing from the iTunes app on Mojave, this parameter is present, so everything works.

Unfortunately, I can't figure out what to replace this missing parameter with, so for the moment, all we can say that Shairport Sync is not compatible with Mac OS Mojave.

github-actions[bot] commented 3 years ago

This issue has been inactive for 60 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.