[Problem]: “Bus error (core dumped)” when trying to play a playlist from OwnTone with MQTT enabled

[aaronk6]

What happened?

When I try to play a playlist from OwnTone on a shairport-sync speaker, shairport-sync crashes with the message “Bus error (core dumped)”.

I’m still investigating this, but I can reliably reproduce this with multiple playlists that contain Spotify tracks. In contrast, radio streams (via OwnTone) work fine.

I will add more findings later, but maybe this is already helpful at this stage. Let me know if there’s anything else I should try to narrow it down.

Relevant log output

bad_dg_1     |         48.034405397 "rtsp.c:5677" Connection 3: New connection from 192.168.88.150:59118 to self at 192.168.88.8:7000.
bad_dg_1     |          0.000695982 "rtsp.c:2632" OPTIONS request
bad_dg_1     |          0.001671129 "rtsp.c:2632"   Type: "CSeq", content: "1"
bad_dg_1     |          0.000050019 "rtsp.c:2632"   Type: "User-Agent", content: "owntone/28.10"
bad_dg_1     |          0.000047611 "rtsp.c:2632"   Type: "Client-Instance", content: "68906BCA5356CD45"
bad_dg_1     |          0.000044815 "rtsp.c:2632"   Type: "DACP-ID", content: "68906BCA5356CD45"
bad_dg_1     |          0.000042963 "rtsp.c:2632"   Type: "Active-Remote", content: "3232258051"
bad_dg_1     |          0.000041074 "rtsp.c:2632"   No Content Plist. Content length: 0.
bad_dg_1     |          0.001705907 "rtsp.c:4497" Connection 3: ANNOUNCE
bad_dg_1     |          0.000074834 "rtsp.c:586" Connection 3: request to acquire principal_conn.
bad_dg_1     |          0.000048240 "rtsp.c:4501" Connection 3: ANNOUNCE has acquired play lock.
bad_dg_1     |          0.003470852 "rtsp.c:4543" Connection 3: Classic AirPlay connection from 192.168.88.150:59118 to self at 192.168.88.8:7000.
bad_dg_1     |          0.000103074 "rtsp.c:4719" Play connection from user agent "owntone/28.10" on RTSP conversation thread 3.
bad_dg_1     |          0.000502148 "rtsp.c:4751" Connection 3: ANNOUNCE has completed.
bad_dg_1     |          0.001764871 "rtsp.c:3453" Connection 3: SETUP
bad_dg_1     |          0.000074592 "rtsp.c:3460" Connection 3: SETUP: Active-Remote string seen: "3232258051".
bad_dg_1     |          0.002293482 "mqtt.c:108" [MQTT]: publishing under shairport-sync/bad_dg/active_remote_id
bad_dg_1     |          0.000169704 "rtsp.c:3480" Connection 3: SETUP: DACP-ID string seen: "68906BCA5356CD45".
bad_dg_1     |          0.000427518 "mqtt.c:108" [MQTT]: publishing under shairport-sync/bad_dg/dacp_id
bad_dg_1     |          0.000150222 "rtp.c:1033" Connection 3: SETUP -- Connection from 192.168.88.150 to self at 192.168.88.8.
bad_dg_1     |          0.000282908 "rtsp.c:3542" Connection 3: SETUP DACP-ID "68906BCA5356CD45" from 192.168.88.150 to 192.168.88.8 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
bad_dg_1     |          0.000503537 "metadata_hub.c:570" MH Client IP set to: "192.168.88.150"
bad_dg_1     |          0.000388722 "mqtt.c:108" [MQTT]: publishing under shairport-sync/bad_dg/client_ip
bad_dg_1     |          0.000563981 "mqtt.c:108" [MQTT]: publishing under shairport-sync/bad_dg/server_ip
bad_dg_1     |          0.001666482 "rtsp.c:1575" Connection 3: RECORD
bad_dg_1     |          0.000051648 "dbus-service.c:226" Build metadata
bad_dg_1     |          0.000017000 "rtsp.c:1581" Connection 3: Classic AirPlay connection from 192.168.88.150:59118 to self at 192.168.88.8:7000.
bad_dg_1     |          0.000066685 "activity_monitor.c:64" abeg
bad_dg_1     |          0.000564389 "mqtt.c:108" [MQTT]: publishing under shairport-sync/bad_dg/active_start
bad_dg_1     |          0.000601482 "player.c:3611" Connection 3: player_play.
bad_dg_1     |          0.000787981 "mqtt.c:108" [MQTT]: publishing under shairport-sync/bad_dg/play_start
bad_dg_1     |          0.000654556 "activity_monitor.c:167" am_state: am_active
bad_dg_1     |          0.001466814 "rtsp.c:3612" Connection 3: request to set AirPlay Volume to: -10.800000.
bad_dg_1     |          0.004714556 "mpris-service.c:167" Build metadata
bad_dg_1     |          0.001986778 "metadata_hub.c:622" MH Server IP set to: "192.168.88.8"
bad_dg_1     |          0.002056685 "dbus-service.c:226" Build metadata
bad_dg_1     |          0.000876981 "dbus-service.c:636" >> setting volume to -10.8000.
bad_dg_1     |          0.000084537 "player.c:3476" Software attenuation set to -1733.400031, i.e 8907.993989 out of 65,536, for airplay volume of -10.800000
bad_dg_1     |          0.000038149 "loudness.c:47" Volume: -17.3 dB - Loudness gain @10Hz: 0.0 dB
bad_dg_1     |          0.000084314 "player.c:3517" player_volume_without_notification: volume mode is 0, airplay volume is -10.80, software_attenuation dB: -17.33, hardware_attenuation dB: 0.00, muting is disabled.
bad_dg_1     |          0.000284778 "mqtt.c:108" [MQTT]: publishing under shairport-sync/bad_dg/volume
bad_dg_1     |          0.002194259 "mpris-service.c:167" Build metadata
bad_dg_1     |          0.001548815 "dbus-service.c:226" Build metadata
bad_dg_1     |          0.000555834 "mpris-service.c:167" Build metadata
bad_dg_1     |          0.001010222 "mqtt.c:108" [MQTT]: publishing under shairport-sync/bad_dg/title
bad_dg_1     | Bus error (core dumped)
bad_dg_1     | s6-rc: info: service legacy-services: stopping
bad_dg_1     | s6-rc: info: service legacy-services successfully stopped
bad_dg_1     | s6-rc: info: service syslogd: stopping
bad_dg_1     | s6-rc: info: service 04-nqptp: stopping
bad_dg_1     | s6-rc: info: service 03-avahi: stopping
bad_dg_1     | Got SIGTERM, quitting.

System Information.

Raspberry Pi 4 (2 GB)

Configuration Information.

# shairport-sync --displayConfig
         0.000969407 "shairport.c:2129" >> Display Config Start.
         0.006077056 "shairport.c:2129"
         0.000043481 "shairport.c:2129" From "uname -a":
         0.000154334 "shairport.c:2129"  Linux dc15a8711008 6.1.0-rpi4-rpi-v8 #1 SMP PREEMPT Debian 1:6.1.54-1+rpt2 (2023-10-05) aarch64 Linux
         0.008257481 "shairport.c:2129"
         0.000046130 "shairport.c:2129" From /etc/os-release:
         0.000048926 "shairport.c:2129"  Alpine Linux v3.17
         0.003254870 "shairport.c:2129"
         0.000076519 "shairport.c:2129" Shairport Sync Version String:
         0.000042018 "shairport.c:2129"  4.3.4-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc
         0.000103778 "shairport.c:2129"
         0.000054148 "shairport.c:2129" Command Line:
         0.000388056 "shairport.c:2129"  shairport-sync --displayConfig
         0.000153870 "shairport.c:2129"
         0.000047482 "shairport.c:2129" Configuration File:
         0.000043666 "shairport.c:2129"  /etc/shairport-sync.conf
         0.000039148 "shairport.c:2129"
         0.000656500 "shairport.c:2129" Configuration File Settings:
         0.000058778 "shairport.c:2129"  general :
         0.000041871 "shairport.c:2129"  {
         0.000043796 "shairport.c:2129"    name = "Bad DG";
         0.000043111 "shairport.c:2129"    output_backend = "pa";
         0.000038926 "shairport.c:2129"    airplay_device_id = 0x242C0A85803L;
         0.000228370 "shairport.c:2129"  };
         0.000227926 "shairport.c:2129"  sessioncontrol :
         0.000024759 "shairport.c:2129"  {
         0.000032112 "shairport.c:2129"    allow_session_interruption = "yes";
         0.000019111 "shairport.c:2129"  };
         0.000027166 "shairport.c:2129"  pa :
         0.000019648 "shairport.c:2129"  {
         0.000019408 "shairport.c:2129"    sink = "bad_dg";
         0.000018852 "shairport.c:2129"  };
         0.000122185 "shairport.c:2129"  diagnostics :
         0.000187759 "shairport.c:2129"  {
         0.000041519 "shairport.c:2129"    log_verbosity = 2;
         0.000060166 "shairport.c:2129"  };
         0.000048871 "shairport.c:2129"  metadata :
         0.000038333 "shairport.c:2129"  {
         0.000037167 "shairport.c:2129"    enabled = "yes";
         0.000117981 "shairport.c:2129"    include_cover_art = "yes";
         0.000071685 "shairport.c:2129"    cover_art_cache_directory = "/tmp/shairport-sync/.cache/coverart";
         0.000070241 "shairport.c:2129"    pipe_name = "/tmp/shairport-sync-metadata";
         0.000056019 "shairport.c:2129"    pipe_timeout = 5000;
         0.000032314 "shairport.c:2129"  };
         0.000019926 "shairport.c:2129"  mqtt :
         0.000019056 "shairport.c:2129"  {
         0.000019259 "shairport.c:2129"    enabled = "yes";
         0.000019241 "shairport.c:2129"    hostname = "homeassistant.example.com";
         0.000193648 "shairport.c:2129"    port = 1883;
         0.000021722 "shairport.c:2129"    username = "shairport";
         0.000017778 "shairport.c:2129"    password = "redacted";
         0.000031519 "shairport.c:2129"    topic = "shairport-sync/bad_dg";
         0.000040592 "shairport.c:2129"    publish_raw = "no";
         0.000038519 "shairport.c:2129"    publish_parsed = "yes";
         0.000038778 "shairport.c:2129"    publish_cover = "no";
         0.000040388 "shairport.c:2129"    enable_autodiscovery = "yes";
         0.000116926 "shairport.c:2129"    enable_remote = "no";
         0.000231463 "shairport.c:2129"  };
         0.000023297 "shairport.c:2129"
         0.000017648 "shairport.c:2129" >> Display Config End.
         0.000031666 "shairport.c:2131" >> Goodbye!
         0.000044389 "shairport.c:1592" exit function called...
         0.000059908 "shairport.c:1602" Stopping the activity monitor.
         0.000040777 "shairport.c:1604" Stopping the activity monitor done.
         0.000063445 "shairport.c:1607" Stopping DACP Monitor
         0.000043333 "shairport.c:1609" Stopping DACP Monitor Done
         0.000038611 "shairport.c:1620" Stopping D-Bus service
         0.000377556 "dbus-service.c:1219" stopping dbus service
         0.000176611 "shairport.c:1622" Stopping D-Bus service done
         0.000139685 "shairport.c:1638" Stopping metadata hub
         0.000022945 "shairport.c:1640" Stopping metadata done
         0.000018000 "shairport.c:1644" Stopping metadata
         0.000038074 "shairport.c:1646" Stopping metadata done
         0.000125018 "shairport.c:1729" normal exit

PulseAudio or PipeWire installed?

• Check if your system uses a Sound Server.

How did you install Shairport Sync?

Docker

Check previous issues

• Confirm

[aaronk6]

Turns out it only happens when MQTT is enabled.

[mikebrady]

Thanks. I’m away from my machines for about the next two weeks, so it’ll take a little while to fix this, I’m afraid.

[aaronk6]

No worries, I’ll see if I can further narrow it done in the meantime.

[mikebrady]

Before I dig in to this, I was just wondering if you had succeeded in narrowing this problem down at all? Is it reliably reproducible?

[aaronk6]

It only happens with certain combinations and is not clearly tied to MQTT. Let me revisit this in the next days to create an overview of the combinations I tried.

[aaronk6]

Thanks for your patience. I eventually ran a few more tests.

❌ Issue occurs:

• MQTT enabled, play local file or Spotify track via OwnTone

✅ Issue does not occur:

• MQTT disabled, play local file or Spotify track via OwnTone
• MQTT enabled, play radio stream via OwnTone
• MQTT enabled, stream audio from iOS (tested with Spotify)

Tested with 4.3.5-dev-55-gab6225c1-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-pa-pw-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc (Docker).

Any idea what this could be or what else would be helpful for me to try?

[aaronk6]

My first guess was that it has something to do with the title sent via MQTT, as it’s crashing right after this log message:

0.001010222 "mqtt.c:108" [MQTT]: publishing under shairport-sync/bad_dg/title

However, even after modifying mqtt_publish as shown below, it still crashes when playing a file via OwnTone.

void mqtt_publish(char *topic, char *data_in, uint32_t length_in) {
  debug(2, "[MQTT]: NOT publishing! (for debugging)");
  return;
}

Results in:

bad_dg_1     |          0.001188759 "mqtt.c:97" [MQTT]: NOT publishing! (for debugging)
bad_dg_1     | Bus error (core dumped)