[Problem]: Crash on starting a session from iPhone to raspberry

[xska2]

What happened?

1. on iPhone connect to raspberry pi
2. Start playing from Spotify - it shows "airplay handoff device" instead of the actual name, there is no sound
3. shairport crashes

Relevant log output

Oct 07 10:49:36 raspberrypi shairport-sync[5327]: --
Oct 07 10:49:36 raspberrypi shairport-sync[5327]:          0.000035468 "rtsp.c:1538" Responding with content of length 104
Oct 07 10:49:36 raspberrypi shairport-sync[5327]:          0.003570990 "mdns_avahi.c:496" dacp_monitor for "822A510965105E69"
Oct 07 10:49:36 raspberrypi shairport-sync[5327]:          0.000095208 "player.c:2182" Set initial volume to -11.250000.
Oct 07 10:49:36 raspberrypi shairport-sync[5327]:          0.001206615 "audio_alsa.c:2050" mute(0) set_mute_state
Oct 07 10:49:36 raspberrypi shairport-sync[5327]:          0.000059948 "player.c:3362" player_volume_without_notification: volume mode is 1, airplay volume is -11.25, software_attenuation dB: 0.00, hardware_attenuation dB: -7.25, muti
Oct 07 10:49:36 raspberrypi shairport-sync[5327]:          0.000034427 "player.c:2185" Play begin
Oct 07 10:49:36 raspberrypi shairport-sync[5327]:          0.001417916 "rtp.c:1737" AP2 Realtime Clock receiver initialised.
Oct 07 10:49:36 raspberrypi shairport-sync[5327]:          0.000097292 "rtp.c:1754" First packet is a sentinel packet.
Oct 07 10:49:36 raspberrypi shairport-sync[5327]:          0.000055208 "rtp.c:1277" set_ptp_anchor_info: clock: 908c4323db2e0008, rtptime: 2478987695, networktime: 2538b64c537ee.
Oct 07 10:49:36 raspberrypi shairport-sync[5327]:          0.000023230 "rtp.c:1280" Connection 5: Set Anchor Clock: 908c4323db2e0008.
Oct 07 10:49:36 raspberrypi systemd[1]: shairport-sync.service: Main process exited, code=killed, status=11/SEGV
Oct 07 10:49:36 raspberrypi systemd[1]: shairport-sync.service: Failed with result 'signal'.

Operating System?

Linux raspberrypi 5.10.103-v7+ #1529 SMP Tue Mar 8 12:21:37 GMT 2022 armv7l GNU/Linux

Version?

4.1-dev-625-g2a702979-AirPlay2-alac-libdaemon-OpenSSL-Avahi-ALSA-soxr-convolution-sysconfdir:/etc

How did you install Shairport Sync?

Built from source

Check previous issues

• [X] Confirm

[xska2]

crash.log

[mikebrady]

Thanks. This looks like #1548!

[mikebrady]

I'll be posting updates on #1548.

[mikebrady]

@xska2, a solution has been found for #1548, and it might apply to your issue too. If you got a chance to try it out -- it's been pushed into the development branch -- and let us know if it works, that would be great.

[xska2]

Thanks, will check it out and report back.

[xska2]

@mikebrady unfortunately, it still reproduces running the latest development branch.

Version: 4.1-rc0-101-ge4bb1447-AirPlay2-alac-libdaemon-OpenSSL-Avahi-ALSA-soxr-convolution-sysconfdir:/etc

Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.000068177 "rtsp.c:1538" Responding with content of length 104
Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.007799688 "rtp.c:1737" AP2 Realtime Clock receiver initialised.
Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.000178021 "rtp.c:1754" First packet is a sentinel packet.
Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.000121041 "rtp.c:1277" set_ptp_anchor_info: clock: 908c4323db2e0008, rtptime: 3364387009, networktime: 2e7cd74150d6f.
Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.000048646 "rtp.c:1280" Connection 1: Set Anchor Clock: 908c4323db2e0008.
Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.004911302 "mdns_avahi.c:496" dacp_monitor for "FDCD7C85C947ADCF"
Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.000133854 "player.c:2182" Set initial volume to -24.000000.
Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.001096563 "audio_alsa.c:2050" mute(0) set_mute_state
Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.000115156 "player.c:3362" player_volume_without_notification: volume mode is 1, airplay volume is -24.00, software_atte
Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.000069844 "player.c:2185" Play begin
Oct 11 07:45:59 raspberrypi shairport-sync[26815]:          0.000077240 "rtp.c:1410" Connection 1: NQPTP master clock 908c4323db2e0008.
Oct 11 07:45:59 raspberrypi systemd[1]: shairport-sync.service: Main process exited, code=killed, status=11/SEGV
Oct 11 07:45:59 raspberrypi systemd[1]: shairport-sync.service: Failed with result 'signal'.

[xska2]

The issue only reproduces occasionally, but it crashed three times this morning before starting to work. When it does work, it carries on like this:

Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.000065208 "rtsp.c:1538" Responding with content of length 104
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.006511510 "rtp.c:1737" AP2 Realtime Clock receiver initialised.
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.000185053 "rtp.c:1754" First packet is a sentinel packet.
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.000114479 "rtp.c:1277" set_ptp_anchor_info: clock: 908c4323db2e0008, rtptime: 1191595436, networktime: 2e7e0726b6722.
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.000049687 "rtp.c:1280" Connection 1: Set Anchor Clock: 908c4323db2e0008.
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.005886615 "mdns_avahi.c:496" dacp_monitor for "9F5ADD8A5F0216DF"
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.000126458 "player.c:2182" Set initial volume to -24.000000.
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.000592292 "audio_alsa.c:2050" mute(0) set_mute_state
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.000060260 "player.c:3362" player_volume_without_notification: volume mode is 1, airplay volume is -24.00, software_atte
nuation dB: 0.00, hardware_attenuation dB: -30.20, muting is disabled.
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.000052292 "player.c:2185" Play begin
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.000058489 "rtp.c:1410" Connection 1: NQPTP master clock 908c4323db2e0008.
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.021830469 "player.c:435" Connection 1: synced by first packet, seqno 29127.
Oct 11 07:50:24 raspberrypi shairport-sync[26919]:          0.000132396 "player.c:160" Apple ALAC Decoder used on encrypted audio.

which makes me suspect that the issue is somewhere between these two lines:

Oct 11 07:50:24 raspberrypi shairport-sync[26919]: 0.000058489 "rtp.c:1410" Connection 1: NQPTP master clock 908c4323db2e0008. and Oct 11 07:50:24 raspberrypi shairport-sync[26919]: 0.021830469 "player.c:435" Connection 1: synced by first packet, seqno 29127.

[mikebrady]

Thanks for the information!

[mikebrady]

Quick question. What settings have you made, please? I'm thinking of settings on the command line and non-default settings in the configuration file, so that I can try to reproduce the environment.

[mikebrady]

Actually, an update has just been pushed to the development folder which has a new option for just this purpose of getting this configuration information. When you get a chance to update, if you execute $ shairport-sync --displayConfig on the command line, it will print the configuration information I was wondering about, and if you could post that, it would be great.

One slightly heavy-duty way to try to locate this bug is to get a core dump from a crash and send it. It's heavy-duty because the core dump can be pretty big, around 150 MB. And there are one or two settings that would make it much more useful to us. If you were willing, please let us know and we'll post a few simple instructions.

[Update] I guess a less heavy-duty way would be to generate the dump from a crash and for you to run gdb on it yourself...

[xska2]

Absolutely, not a problem. I just need to figure out how to enable coredumps in the systemd service

Here is the --displayConfig output:

pi@raspberrypi:~/shairport-sync $ shairport-sync --displayConfig
         0.002176511 "shairport.c:1473" default pid filename is "/var/run/shairport-sync".
>> Display Config Start.

Version String:
4.1-rc0-121-g16ca1c9f-AirPlay2-alac-libdaemon-OpenSSL-Avahi-ALSA-soxr-convolution-sysconfdir:/etc

Command Line:
shairport-sync (null)

Configuration File:
/etc/shairport-sync.conf

Configuration File Settings:
general :
{
  interpolation = "soxr";
  volume_range_db = 60;
};
sessioncontrol :
{
};
alsa :
{
  output_device = "hw:0";
  mixer_control_name = "Headphone";
};
sndio :
{
};
pa :
{
};
jack :
{
};
pipe :
{
};
dsp :
{
  convolution = "no";
  loudness = "no";
};
metadata :
{
};
mqtt :
{
};
diagnostics :
{
  statistics = "yes";
  log_verbosity = 2;
};

>> Display Config End.
>> Goodbye!
         0.001494375 "shairport.c:1524" exit function called...
         0.000082916 "shairport.c:1571" Stopping the activity monitor.
         0.000023125 "shairport.c:1581" Waiting for SoXr timecheck to terminate...
         0.000051094 "shairport.c:1643" exit_function libdaemon exit

[xska2]

Ok, looks like I needed to install systemd-coredump, hopefully will have a core next time it happens.

[xska2]

As luck has it, I tried to play something just after and it crashed:

Oct 11 23:26:25 raspberrypi systemd[1]: shairport-sync.service: Main process exited, code=killed, status=11/SEGV
Oct 11 23:26:25 raspberrypi systemd[1]: shairport-sync.service: Failed with result 'signal'.
Oct 11 23:26:28 raspberrypi systemd-coredump[11830]: Process 11808 (shairport-sync) of user 995 dumped core.

                                                     Stack trace of thread 11827:
                                                     #0  0x00000000757472d0 n/a (libsodium.so.23)

Let me know what commands would you like me to run on the core / gdb.

[mikebrady]

Many thanks for this. If you could pull the latest version (there's some small updates) and go through the full $ autoreconf -fi, $ ./configure... stuff, but with a twist: please precede the ./configure stuff with a few definitions to ask the compiler to turn off optimisations, (to improve debugging). Your ./configure... line should now look something like this:

$ CFLAGS="-O0 -g" CXXFLAGS="-O0 -g" ./configure...

Everything after the ./configure should be the same as before. Then to a $ make clean and a $ make.

Let's presume you run Shairport Sync from the command line:

$ ./shairport-sync -v

and it crashes.

Then, in the same directory, enter:

$ gdb ./shairport-sync core

(presuming the core file is called core)

Then, you should be able to do a backtrace:

(gdb) bt full

The output from this may give us a hint as to where in Shairport Sync the crash occurred.

Here's hoping!

[xska2]

Done:

(gdb) bt full
#0  0x757662d0 in  () at /usr/lib/arm-linux-gnueabihf/libsodium.so.23
#1  0x757413ac in crypto_aead_chacha20poly1305_ietf_decrypt_detached () at /usr/lib/arm-linux-gnueabihf/libsodium.so.23
#2  0xfffffffe in  ()

I've also done thread apply all bt full just in case. It got a bit long, so attaching as a file.

stacktrace.txt

[mikebrady]

Thanks great thanks -- I'll go off any study that now. Could I ask you to run the $ shairport-sync --displayConfig again, please? It's gathering a little more information and I'd really like to be able to reproduce the situation locally.

[xska2]

Of course, here you go:

pi@raspberrypi:~ $ shairport-sync --displayConfig
         0.002189115 "shairport.c:1474" default pid filename is "/var/run/shairport-sync".
         0.000181250 "shairport.c:1984" >> Display Config Start.
         0.010991875 "shairport.c:1984"
         0.000142656 "shairport.c:1984" From "uname -a":
         0.000055417 "shairport.c:1984"  Linux raspberrypi 5.10.103-v7+ #1529 SMP Tue Mar 8 12:21:37 GMT 2022 armv7l GNU/Linux
         0.015316250 "shairport.c:1984"
         0.000162604 "shairport.c:1984" From /etc/os-release:
         0.000063437 "shairport.c:1984"  Raspbian GNU/Linux 10 (buster)
         0.012847813 "shairport.c:1984"
         0.000138593 "shairport.c:1984" From /sys/firmware/devicetree/base/model:
         0.000056615 "shairport.c:1984"  Raspberry Pi 3 Model B Rev 1.2
         0.000130260 "shairport.c:1984"
         0.000055313 "shairport.c:1984" Shairport Sync Version String:
         0.000194687 "shairport.c:1984"  4.1-rc0-125-g15b60fe8-AirPlay2-alac-libdaemon-OpenSSL-Avahi-ALSA-soxr-convolution-sysconfdir:/etc
         0.000098907 "shairport.c:1984"
         0.000076823 "shairport.c:1984" Command Line:
         0.000161406 "shairport.c:1984"  shairport-sync --displayConfig
         0.000316458 "shairport.c:1984"
         0.000062709 "shairport.c:1984" Configuration File:
         0.000057343 "shairport.c:1984"  /etc/shairport-sync.conf
         0.000051719 "shairport.c:1984"
         0.000171563 "shairport.c:1984" Configuration File Settings:
         0.000329114 "shairport.c:1984"  general :
         0.000030365 "shairport.c:1984"  {
         0.000022760 "shairport.c:1984"    interpolation = "soxr";
         0.000021042 "shairport.c:1984"    volume_range_db = 60;
         0.000020104 "shairport.c:1984"  };
         0.000050260 "shairport.c:1984"  sessioncontrol :
         0.000092709 "shairport.c:1984"  {
         0.000211250 "shairport.c:1984"  };
         0.000046354 "shairport.c:1984"  alsa :
         0.000021510 "shairport.c:1984"  {
         0.000098646 "shairport.c:1984"    output_device = "hw:0";
         0.000023542 "shairport.c:1984"    mixer_control_name = "Headphone";
         0.000049166 "shairport.c:1984"  };
         0.000020261 "shairport.c:1984"  sndio :
         0.000019583 "shairport.c:1984"  {
         0.000018959 "shairport.c:1984"  };
         0.000046197 "shairport.c:1984"  pa :
         0.000020105 "shairport.c:1984"  {
         0.000019375 "shairport.c:1984"  };
         0.000073125 "shairport.c:1984"  jack :
         0.000193437 "shairport.c:1984"  {
         0.000224063 "shairport.c:1984"  };
         0.000125468 "shairport.c:1984"  pipe :
         0.000022552 "shairport.c:1984"  {
         0.000019740 "shairport.c:1984"  };
         0.000046563 "shairport.c:1984"  dsp :
         0.000020885 "shairport.c:1984"  {
         0.000034479 "shairport.c:1984"    convolution = "no";
         0.000163021 "shairport.c:1984"    loudness = "no";
         0.000242656 "shairport.c:1984"  };
         0.000047709 "shairport.c:1984"  metadata :
         0.000021822 "shairport.c:1984"  {
         0.000102240 "shairport.c:1984"  };
         0.000049375 "shairport.c:1984"  mqtt :
         0.000058750 "shairport.c:1984"  {
         0.000079792 "shairport.c:1984"  };
         0.000248281 "shairport.c:1984"  diagnostics :
         0.000054323 "shairport.c:1984"  {
         0.000137760 "shairport.c:1984"    statistics = "yes";
         0.000077813 "shairport.c:1984"    log_verbosity = 2;
         0.000080989 "shairport.c:1984"  };
         0.000162188 "shairport.c:1984"
         0.000083437 "shairport.c:1984" >> Display Config End.
         0.000046302 "shairport.c:1986" >> Goodbye!
         0.000196980 "shairport.c:1525" exit function called...
         0.000050885 "shairport.c:1577" Stopping the activity monitor.
         0.000024688 "shairport.c:1579" Stopping the activity monitor done.
         0.000066145 "shairport.c:1658" exit_function libdaemon exit

[mikebrady]

Great stuff -- thanks again. I'll try to reproduce this here -- I have just such a Pi, and, frustratingly, it's working fine. Here is its readout (log_verbosity is 0):

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

From "uname -a":
 Linux RaspberryPi3B 5.15.61-v7+ #1579 SMP Fri Aug 26 11:10:59 BST 2022 armv7l GNU/Linux

From /etc/os-release:
 Raspbian GNU/Linux 11 (bullseye)

From /sys/firmware/devicetree/base/model:
 Raspberry Pi 3 Model B Rev 1.2

Shairport Sync Version String:
 4.1-dev-727-g15b60fe8-AirPlay2-OpenSSL-Avahi-ALSA-sndio-jack-ao-pa-soundio-dummy-stdout-pipe-soxr-metadata-mqtt-dbus-mpris-sysconfdir:/etc

Command Line:
 shairport-sync --displayConfig

Configuration File:
 /etc/shairport-sync.conf

Configuration File Settings:
 general : 
 {
   name = "Speakers!";
   volume_range_db = 70;
   run_this_when_volume_is_set = "/usr/bin/echo ";
 };
 sessioncontrol : 
 {
   run_this_before_entering_active_state = "/usr/bin/logger \"Active Start\"";
   run_this_after_exiting_active_state = "/usr/bin/logger \"Active End\"";
 };
 alsa : 
 {
   output_device = "hw:sndrpihifiberry";
   disable_standby_mode = "always";
 };
 sndio : 
 {
 };
 pa : 
 {
 };
 jack : 
 {
 };
 pipe : 
 {
 };
 dsp : 
 {
 };
 metadata : 
 {
 };
 mqtt : 
 {
 };
 diagnostics : 
 {
   statistics = "yes";
 };

>> Display Config End.
>> Goodbye!

[mikebrady]

I'll take closer look tomorrow (it's nighttime here).

[xska2]

Just in case this helps, the libsodium version I have is:

pi@raspberrypi:~ $ ldd /usr/local/bin/shairport-sync | grep sodium
        libsodium.so.23 => /usr/lib/arm-linux-gnueabihf/libsodium.so.23 (0x757a3000)
pi@raspberrypi:~ $ dpkg -l | grep sodium
ii  libsodium-dev:armhf                  1.0.17-1                                armhf        Network communication, cryptography and signaturing library - headers
ii  libsodium23:armhf                    1.0.17-1                                armhf        Network communication, cryptography and signaturing library

[mikebrady]

Thanks. A slight difference here:

pi@RaspberryPi3B:~ $ ldd /usr/local/bin/shairport-sync | grep sodium
    libsodium.so.23 => /lib/arm-linux-gnueabihf/libsodium.so.23 (0x756e0000)
pi@RaspberryPi3B:~ $ dpkg -l | grep sodium
ii  libsodium-dev:armhf                  1.0.18-1                         armhf        Network communication, cryptography and signaturing library - headers
ii  libsodium23:armhf                    1.0.18-1                         armhf        Network communication, cryptography and signaturing library

Something to check up on...

[mikebrady]

Hmm, nothing obvious in the libsodium ChangeLog.

[mikebrady]

Could I just check what version of Spotify and iOS? I'm using iOS 16.0.3 and Spotify 8.7.68.568.

[mikebrady]

Start playing from Spotify - it shows "airplay handoff device" instead of the actual name, there is no sound

I don't get that. Instead, I get Devices > Connect to a device > Current device > AirPlay or Bluetooth. Then the regular AirPlay speaker panel opens up and I see the named device ("Xska2" in this case).

[mikebrady]

Do you happen to have any firewalls running on the Pi or on your network?

[mikebrady]

BTW, this is my setup now...

$ shairport-sync --displayConfig
         0.002256198 "shairport.c:1474" default pid filename is "/var/run/shairport-sync".
         0.000116823 "shairport.c:1984" >> Display Config Start.
         0.010857864 "shairport.c:1984" 
         0.000084844 "shairport.c:1984" From "uname -a":
         0.000025052 "shairport.c:1984"  Linux xska2 5.10.103-v7+ #1529 SMP Tue Mar 8 12:21:37 GMT 2022 armv7l GNU/Linux
         0.014702865 "shairport.c:1984" 
         0.000151614 "shairport.c:1984" From /etc/os-release:
         0.000056823 "shairport.c:1984"  Raspbian GNU/Linux 10 (buster)
         0.012696198 "shairport.c:1984" 
         0.000133437 "shairport.c:1984" From /sys/firmware/devicetree/base/model:
         0.000055105 "shairport.c:1984"  Raspberry Pi 3 Model B Rev 1.2
         0.000127395 "shairport.c:1984" 
         0.000094740 "shairport.c:1984" Shairport Sync Version String:
         0.000072031 "shairport.c:1984"  4.1-dev-727-g15b60fe8-AirPlay2-alac-libdaemon-OpenSSL-Avahi-ALSA-soxr-convolution-sysconfdir:/etc
         0.000161823 "shairport.c:1984" 
         0.000098802 "shairport.c:1984" Command Line:
         0.000063542 "shairport.c:1984"  shairport-sync --displayConfig
         0.000148385 "shairport.c:1984" 
         0.000055730 "shairport.c:1984" Configuration File:
         0.000055416 "shairport.c:1984"  /etc/shairport-sync.conf
         0.000054531 "shairport.c:1984" 
         0.000055105 "shairport.c:1984" Configuration File Settings:
         0.000202448 "shairport.c:1984"  general : 
         0.000058333 "shairport.c:1984"  {
         0.000051875 "shairport.c:1984"    interpolation = "soxr";
         0.000052396 "shairport.c:1984"    volume_range_db = 60;
         0.000051875 "shairport.c:1984"  };
         0.000051041 "shairport.c:1984"  sessioncontrol : 
         0.000054688 "shairport.c:1984"  {
         0.000054375 "shairport.c:1984"  };
         0.000054375 "shairport.c:1984"  alsa : 
         0.000054323 "shairport.c:1984"  {
         0.000054375 "shairport.c:1984"    output_device = "hw:0";
         0.000055104 "shairport.c:1984"    mixer_control_name = "Headphone";
         0.000056146 "shairport.c:1984"  };
         0.000054271 "shairport.c:1984"  sndio : 
         0.000054479 "shairport.c:1984"  {
         0.000055729 "shairport.c:1984"  };
         0.000050885 "shairport.c:1984"  pa : 
         0.000054792 "shairport.c:1984"  {
         0.000051406 "shairport.c:1984"  };
         0.000041354 "shairport.c:1984"  jack : 
         0.000022500 "shairport.c:1984"  {
         0.000021615 "shairport.c:1984"  };
         0.000021302 "shairport.c:1984"  pipe : 
         0.000021354 "shairport.c:1984"  {
         0.000020886 "shairport.c:1984"  };
         0.000021146 "shairport.c:1984"  dsp : 
         0.000021197 "shairport.c:1984"  {
         0.000021042 "shairport.c:1984"    convolution = "no";
         0.000021719 "shairport.c:1984"    loudness = "no";
         0.000021510 "shairport.c:1984"  };
         0.000021042 "shairport.c:1984"  metadata : 
         0.000021406 "shairport.c:1984"  {
         0.000020990 "shairport.c:1984"  };
         0.000021250 "shairport.c:1984"  mqtt : 
         0.000021198 "shairport.c:1984"  {
         0.000021146 "shairport.c:1984"  };
         0.000021093 "shairport.c:1984"  diagnostics : 
         0.000021198 "shairport.c:1984"  {
         0.000021146 "shairport.c:1984"    statistics = "yes";
         0.000021563 "shairport.c:1984"    log_verbosity = 2;
         0.000021458 "shairport.c:1984"  };
         0.000041250 "shairport.c:1984" 
         0.000022344 "shairport.c:1984" >> Display Config End.
         0.000040364 "shairport.c:1986" >> Goodbye!
         0.000053438 "shairport.c:1525" exit function called...
         0.000023593 "shairport.c:1577" Stopping the activity monitor.
         0.000021980 "shairport.c:1579" Stopping the activity monitor done.
         0.000058750 "shairport.c:1658" exit_function libdaemon exit

[xska2]

Could I just check what version of Spotify and iOS? I'm using iOS 16.0.3 and Spotify 8.7.68.568.

iOS 15.7, Spotify 8.7.68.568

Do you happen to have any firewalls running on the Pi or on your network?

The Pi is running pi.hole and doing all the DNS/DHCP services for home network.

I don't get that. Instead, I get Devices > Connect to a device > Current device > AirPlay or Bluetooth. Then the regular AirPlay speaker panel opens up and I see the named device ("Xska2" in this case).

What I meant is that after connecting to the device, and starting playing from Spotify it changes the device name to "AIRPLAYHANDOFF DEVICE", and shairport-sync crashes at the same time.

Here is a screenshot of what it looks like when the crash happens:

[mikebrady]

Great stuff, thanks!

[mikebrady]

Thanks again for your interest in this.

My suspicions have fallen on a thread that receives and decrypts packets of audio, but for the life of me, I can't make it happen here, and indeed I can't see how it could be happening.

Anyway, there is a new branch called xska2 with the latest minor updates but also with very noisy debug messages to list information about every audio packet.

If you could try it out and see whether anything unusual shows up prior to a crash, it would be very helpful.

It may be that packets that are valid but empty are being sent, or something lis that, but I just can't make it happen here.

[xska2]

crash running the branch: 4.1-rc0-132-g2cd93873-AirPlay2-alac-libdaemon-OpenSSL-Avahi-ALSA-soxr-convolution-sysconfdir

         0.000417813 "rtsp.c:1538" Responding with content of length 104
         0.000549270 "rtsp.c:892" msg_free freed message 30
         0.000078282 "rtsp.c:892" msg_free freed message 29
         0.006288958 "player.c:1968" Output frame bytes is 4.
         0.000171771 "player.c:1973" dac_buffer_queue_minimum_length is 5292 frames.
         0.000119375 "player.c:2061" Output bit depth is 16.
         0.000042760 "audio_alsa.c:1427" audio_alsa start called.
         0.001615938 "rtp.c:1735" AP2 Realtime Clock receiver initialised.
         0.000162916 "rtp.c:1752" First packet is a sentinel packet.
         0.000101771 "rtp.c:1277" set_ptp_anchor_info: clock: 908c4323db2e0008, rtptime: 1306794445, networktime: 358f7826d06d8.
         0.000043750 "rtp.c:1280" Connection 1: Set Anchor Clock: 908c4323db2e0008.
         0.000416094 "mdns_avahi.c:496" dacp_monitor for "A01B73ACAF069720"
         0.000049583 "player.c:2182" Set initial volume to -24.000000.
         0.000055730 "player.c:3140" mutex_lock "&conn->volume_control_mutex".
         0.000565104 "audio_alsa.c:1983" Setting volume db to -3020.000000.
         0.000293073 "audio_alsa.c:1987" mutex_lock "&alsa_mixer_mutex".
         0.000246979 "audio_alsa.c:281" Open Mixer
         0.000247500 "audio_alsa.c:291" Mixer device name is "hw:0".
         0.000917500 "audio_alsa.c:305" Mixer control is "Headphone",0.
         0.000600000 "common.c:1565" mutex_unlock "&alsa_mixer_mutex" at "audio_alsa.c:2017".
         0.000103385 "audio_alsa.c:2050" mute(0) set_mute_state
         0.000363542 "common.c:1565" mutex_unlock "&alsa_mixer_mutex" at "audio_alsa.c:1419".
         0.000296250 "player.c:3362" player_volume_without_notification: volume mode is 1, airplay volume is -24.00, software_attenuation dB: 0.00, hardware_attenuation dB: -30.20, muting is disabled.
         0.000295989 "common.c:1565" mutex_unlock "&conn->volume_control_mutex" at "player.c:3366".
         0.000286875 "player.c:2185" Play begin
         0.000267865 "ptp-utilities.c:57" mutex_lock "(pthread_mutex_t *)mapped_addr".
         0.000601302 "rtp.c:1410" Connection 1: NQPTP master clock 908c4323db2e0008.
         0.000550990 "mdns_avahi.c:105" resolve_callback: Service 'iTunes_Ctrl_A01B73ACAF069720' of type '_dacp._tcp' in domain 'local':
         0.000166406 "mdns_avahi.c:113" resolve_callback: client dacp_id "A01B73ACAF069720" dacp port: 50437.
         0.001593437 "mdns_avahi.c:105" resolve_callback: Service 'iTunes_Ctrl_A01B73ACAF069720' of type '_dacp._tcp' in domain 'local':
         0.000164532 "mdns_avahi.c:113" resolve_callback: client dacp_id "A01B73ACAF069720" dacp port: 50437.
         0.022427708 "rtp.c:1941" Realtime Audio Receiver Packet received. Version: 2, Padding: 0, Extension: 0, CSRC Count: 0, Marker: 0, Payload Type: 96.
         0.000195833 "rtp.c:1671" Decipher Packet: Size: 66, Sequence Number: 12455, Timestamp: 1306884926.
Segmentation fault (core dumped)

[mikebrady]

Thanks -- the very first packet! However, my guess is that it's a valid packet -- packets of silence appear to take 66 bytes. It may imply that libsodium is being damaged earlier on somewhere. More digging...

[mikebrady]

The pair_ap library, which uses libsodium, was recently updated, so I might switch back to the old version.

[mikebrady]

The pair_ap library has been switched back to the prior version. Again, if you'd be kind enough, could you pull the update and see if it acts differently, please?

[xska2]

Same again I'm afraid:

# shairport-sync -V
4.1-rc0-133-g6cc753bc-AirPlay2-alac-libdaemon-OpenSSL-Avahi-ALSA-soxr-convolution-sysconfdir:/etc

         0.000022553 "audio_alsa.c:281" Open Mixer
         0.000027083 "audio_alsa.c:291" Mixer device name is "hw:0".
         0.000406302 "audio_alsa.c:305" Mixer control is "Headphone",0.
         0.000192969 "common.c:1565" mutex_unlock "&alsa_mixer_mutex" at "audio_alsa.c:2017".
         0.000061198 "audio_alsa.c:2050" mute(0) set_mute_state
         0.000028385 "common.c:1565" mutex_unlock "&alsa_mixer_mutex" at "audio_alsa.c:1419".
         0.000024375 "player.c:3362" player_volume_without_notification: volume mode is 1, airplay volume is -24.00, software_attenuation dB: 0.00, hardware_attenuation dB: -30.20, muting is disabled.
         0.000038125 "common.c:1565" mutex_unlock "&conn->volume_control_mutex" at "player.c:3366".
         0.000026094 "player.c:2185" Play begin
         0.000028281 "ptp-utilities.c:57" mutex_lock "(pthread_mutex_t *)mapped_addr".
         0.000043229 "rtp.c:1410" Connection 1: NQPTP master clock 908c4323db2e0008.
         0.003042552 "mdns_avahi.c:105" resolve_callback: Service 'iTunes_Ctrl_51B42B2CB5B6A90D' of type '_dacp._tcp' in domain 'local':
         0.000072657 "mdns_avahi.c:113" resolve_callback: client dacp_id "51B42B2CB5B6A90D" dacp port: 50866.
         0.002295468 "mdns_avahi.c:105" resolve_callback: Service 'iTunes_Ctrl_51B42B2CB5B6A90D' of type '_dacp._tcp' in domain 'local':
         0.000498282 "mdns_avahi.c:113" resolve_callback: client dacp_id "51B42B2CB5B6A90D" dacp port: 50866.
         0.019004322 "rtp.c:1941" Realtime Audio Receiver Packet received. Version: 2, Padding: 0, Extension: 0, CSRC Count: 0, Marker: 0, Payload Type: 96.
         0.000139063 "rtp.c:1671" Decipher Packet: Size: 66, Sequence Number: 44206, Timestamp: 2456109185.
Segmentation fault (core dumped)

[mikebrady]

Thanks again for your time. Let me take some more time to see what to try next.

[mikebrady]

Back again.

This time, I've added some code to print out the actual encrypted packet and the arguments to crypto_aead_chacha20poly1305_ietf_decrypt, including the session key.

The updated pair_ap has been restored and all the changes are in the same branch -- xsda2.

If you got a chance to run it, crash it and post some of the output, it would be appreciated.

[xska2]

There you go:

         0.016362083 "rtsp.c:807" msg_init message 27
         0.000090209 "rtsp.c:916" RTSP Message Received: "FLUSH rtsp://fd00::635d:55e:5032:387c/15832624568270144231 RTSP/1.0".
         0.000078541 "rtp.c:1944" Realtime Audio Receiver Packet received. Version: 2, Padding: 0, Extension: 0, CSRC Count: 0, Marker: 0, Payload Type: 96.
         0.000099323 "rtp.c:1671" Decipher Packet: Size: 66, Sequence Number: 25508, Timestamp: 915095163.
         0.000127656 "rtp.c:1673" No session key!
         0.000174792 "rtp.c:1675" 63A4368B 3E7B0000 0000B43A 106B2D7A | 21751DA1 5901602A 7E7FD515 F50874BB || 5F7B3830 F5F06A6E 088C0694 14F9A0A7 | 2F59F22D 97EA3FE3 60EC0100 00000000 || 0000
Segmentation fault (core dumped)

[mikebrady]

Fantastic -- there is the cause of the crash: No session key!

[mikebrady]

So, the question is, why?

[mikebrady]

Was there a prior message sequence like this anywhere?

        7.539894320 "rtsp.c:2869" Connection 1: AP2 PTP connection from fd60:823e:c8d5:4746:1802:573a:874f:da0b:49208 ("Mike’s iMac") to self at fd60:823e:c8d5:4746:741c:d0c6:d8bf:ed58:7000.
         0.147756771 "rtsp.c:3157" Size of session key is 32 characters.
         0.000096198 "rtsp.c:3159" 5D01457A CA9B1450 F5302CC6 AD531C71 | 11703A12 1C8911C5 DF106B47 A22BD0AB
         0.000575937 "rtsp.c:3224" Connection 1. AP2 Realtime Audio Stream.
         0.000209323 "rtp.c:1915" AP2 Realtime Audio Receiver startup.
         0.014499480 "rtp.c:1738" AP2 Realtime Clock receiver initialised.

[mikebrady]

So, I've pushed yet another change (!) that will print out the plist that would normally contain the session key if it is missing. (I mean, it might just be that it's in there under a different name...)

[xska2]

Something like this:

         0.000921250 "rtsp.c:2837" Connection 1: SETUP (AirPlay 2)
         0.000210677 "rtsp.c:3144" Connection 1: SETUP on PTP stream. A "streams" array has been found
         0.000155313 "rtsp.c:3163" Connection 1: UDP control port opened: 53537.
         0.000378177 "rtsp.c:3172" Size of session key is 0 characters.
         0.000066198 "rtsp.c:3174"
         0.000051823 "rtsp.c:3180" Connection 1: SETUP AP2 -- Active-Remote string seen: "1838677445".
         0.000051927 "rtsp.c:3200" Connection 1: SETUP AP2 -- DACP-ID string seen: "E8111C2F90984DC5".
         0.000060208 "rtsp.c:3223" Connection 1. AP2 Realtime Audio Stream.
         0.000048594 "rtsp.c:3224" Realtime Audio Stream SETUP incoming message
         0.000046562 "rtsp.c:3224"   Type: "Content-Length", content: "277"
         0.000045938 "rtsp.c:3224"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000048125 "rtsp.c:3224"   Type: "CSeq", content: "12"
         0.000045781 "rtsp.c:3224"   Type: "DACP-ID", content: "E8111C2F90984DC5"
         0.000045208 "rtsp.c:3224"   Type: "Active-Remote", content: "1838677445"
         0.000047553 "rtsp.c:3224"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000347500 "rtsp.c:3224"   Content Plist (as XML):

[xska2]

Ah cool, let me try that.

[xska2]

Here's a fresh log, hope it helps!

fresh_log.txt

[mikebrady]

Thanks. This is (I think) the relevant part of your log:

<?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>streams</key>
        <array>
                <dict>
                        <key>audioFormat</key>
                        <integer>262144</integer>
                        <key>supportsDynamicStreamID</key>
                        <true/>
                        <key>streamConnectionID</key>
                        <integer>4394847767086911410</integer>
                        <key>ct</key>
                        <integer>2</integer>
                        <key>audioMode</key>
                        <string>default</string>
                        <key>spf</key>
                        <integer>352</integer>
                        <key>controlPort</key>
                        <integer>52347</integer>
                        <key>latencyMax</key>
                        <integer>88200</integer>
                        <key>isMedia</key>
                        <true/>
                        <key>type</key>
                        <integer>96</integer>
                        <key>sr</key>
                        <integer>44100</integer>
                        <key>latencyMin</key>
                        <integer>11025</integer>
                </dict>
        </array>
</dict>
</plist>

and this is from my system just now:

<?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>streams</key>
    <array>
        <dict>
            <key>audioFormat</key>
            <integer>262144</integer>
            <key>supportsDynamicStreamID</key>
            <true/>
            <key>streamConnectionID</key>
            <integer>7913311159847636117</integer>
            <key>ct</key>
            <integer>2</integer>
            <key>audioMode</key>
            <string>default</string>
            <key>spf</key>
            <integer>352</integer>
            <key>controlPort</key>
            <integer>56801</integer>
            <key>latencyMax</key>
            <integer>88200</integer>
            <key>isMedia</key>
            <true/>
            <key>type</key>
            <integer>96</integer>
            <key>sr</key>
            <integer>44100</integer>
            <key>shk</key>
            <data>
            UBr+j+Avv5oUGT0vSJR6bsn7jDEgLDA1MSW2YDBSJhQ=
            </data>
            <key>latencyMin</key>
            <integer>11025</integer>
        </dict>
    </array>
</dict>
</plist>

Notice the Session Key (shk) at the bottom of it, missing from yours. I have no idea what that signifies!

[mikebrady]

I'm trying to restore an iPad to 15.7 to see what's happening when Spotify is running from it (I don't really want to reset an iPhone if I don't have to). Also, I can use the absence of the session key to skip decryption so that we might get a few samples of packets, to see if they make any sense. That'll take a little while.

[mikebrady]

Hmm. iPadOS 15.7 on an iPad with Spotify is working fine... 🤷🏼‍♂️

I've added code to skip deciphering audio (but still print it out). I guess there might be a possibility that absence of a session key means it's not encrypted, so it might be worth a look. This is what a frame of silence seems to look like:

20000004 00130809 8FF5EA06 A5FD1813 | 080ABDF5 44030801 6CFF80AF BFE02BFC

[mikebrady]

I have been using the basic, free, Spotify. Are you using the same, or it is a paid-for version?

[xska2]

I have been using the basic, free, Spotify. Are you using the same, or it is a paid-for version?

Mine is a paid-for. I have another Pi (with a similar setup, but model 4B), will try and see if it reproduces there.

[mikebrady]

Thanks. Yes please, if you let us know how that goes, it would be very useful. BTW, the development version has been updated to drop a connection that is missing a session key, so best continue to use the xksa2 branch for experiments here. Maybe it's the fact that it's a paid-for version of Spotify, but it still doesn't make a lot of sense to me.