Music sometimes doesn't start via automation

[johnboiles]

What version of Music Assistant has the issue?

2.4.0b20

Have you tried everything in the Troubleshooting FAQ and reviewed the Open and Closed Issues and Discussions to resolve this yourself?

• Yes

The problem

A few times a week (I haven't found a pattern) my HA automation to play a playlist does not start the music. I see the queue get appropriately populated with the playlist, and music assistant seems to start to play for a few seconds (the button transitions from the play button to the pause button), then it gives up (the UI goes back to the play button)

Opening an issue as promised here.

In the log I see both FFMPEG processes exiting with code 255, which I think means they were killed by MA via a signal.

�[90m2025-01-27 10:51:19.607 VERBOSE (MainThread) [ffmpeg.53] Process ffmpeg with PID 53 stopped with returncode 255�[0m
�[90m2025-01-27 10:51:19.622 VERBOSE (MainThread) [ffmpeg.52] Process ffmpeg with PID 52 stopped with returncode 255�[0m

How to reproduce

Unsure!

Music Providers

Apple Music

Player Providers

HA Media Player w/ Home Assistant Voice ESPHome (Nabu Media Player)

Full log output

d5369777_music_assistant_beta_2025-01-27T18-51-48.554Z.log

Additional information

I've gotten this issue occasionally as long as I've been using MA (since ~September 2024)

What version of Home Assistant Core are your running

2025.1.4

What type of installation are you running?

Home Assistant OS

On what type of hardware are you running?

Raspberry Pi

[OzGav]

Please review the troubleshooting pages of the docs again. You need to narrow this down further so the devs can try and reproduce it.

[johnboiles]

@marcelveldt you mentioned that you've experienced this problem before and have seen reports on it on Discord. Do you have any ideas on how to narrow this further or reproduce? Should I increase the global log level to VERBOSE and see if that exposes anything?

[marcelveldt]

We have only seen this issue being reported with the Voice PE but then it was simply not possible to start music at all (this issue was there every time). A power cycle of the Voice PE fixed the issue. After the recent firmware updates of the Voice PE it was reported as fixed. Anyways, could have been a slightly different issue but it surely looks the same, what you see in the log is that the whole audio chain stops again because the player disconnected again.

Now you mention Apple Music and there is one thing about Apple Music and that is that sometimes retrieving the key takes a while so this could simply be a timeout. Did you ever test any other music source or only Apple Music ?

[johnboiles]

Did you ever test any other music source or only Apple Music ?

No, and it's not so easy for us to test other sources. I only see this 1-3 times per week and I run it in an office with a shared playlist. So to test other sources I'd need to switch our whole office's music for at least a week.

What would be the best way to figure out from logging whether this is an issue with the player or an issue with the music source? If we could start there by adding some logging then we would at least know which direction to pursue.

[marcelveldt]

Is this still happening in the most recent betas (or RC's in the meanwhile) ?

[OzGav]

@johnboiles please see question above.

[johnboiles]

Yeah it still happens regularly. Here's the log from this morning on 2.3.6. I've been on and off the betas too with similar issues. I can try going back to the beta if you think there's a chance this could be fixed.

My question above still remains: What would be the best way to figure out from logging whether this is an issue with the player or an issue with the music source? It looks like from the returncode 255 log that MA is prematurely killing both ffmpeg processes for some reason.

2025-02-25 09:10:05.261 DEBUG (MainThread) [music_assistant.player_queues] Fetching tracks to play for playlist Sol Office Morning
2025-02-25 09:10:05.485 DEBUG (MainThread) [music_assistant.audio] Getting streamdetails for apple_music://track/259593485
2025-02-25 09:10:06.781 DEBUG (MainThread) [music_assistant.audio] retrieved streamdetails for apple_music://track/259593485 in 1296 milliseconds
2025-02-25 09:10:06.882 DEBUG (MainThread) [music_assistant.players] Handling command play_media for player Home Assistant Voice Media Player
2025-02-25 09:10:06.924 VERBOSE (MainThread) [music_assistant.streams] Got GET request to /flow/media_player.home_assistant_voice_media_player/2d151e543ff841b6a1d6d96227cc0d70.mp3 from 192.168.2.170
headers: <CIMultiDictProxy('User-Agent': 'ESP32 HTTP Client/1.0', 'Host': '192.168.1.2:8097', 'Content-Length': '0')>
2025-02-25 09:10:06.926 DEBUG (MainThread) [music_assistant.streams] Start serving Queue flow audio stream for Home Assistant Voice Media Player
2025-02-25 09:10:06.928 VERBOSE (MainThread) [ffmpeg] Process ffmpeg started with PID 52
2025-02-25 09:10:06.928 VERBOSE (MainThread) [ffmpeg.52] started with args: -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp -readrate 1.1 -readrate_initial_burst 10 -ac 2 -channel_layout stereo -ar 48000 -acodec pcm_s16le -f s16le -i - -af alimiter=limit=-2dB:level=false:asc=true -f mp3 -b:a 320k -
2025-02-25 09:10:06.929 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Home Assistant Voice Media Player - crossfade: False
2025-02-25 09:10:06.929 DEBUG (MainThread) [music_assistant.streams] Start Streaming queue track: apple_music--4hmSTk5D://track/259593485 (Mogwai - Christmas Steps) for queue Home Assistant Voice Media Player
2025-02-25 09:10:06.929 DEBUG (MainThread) [music_assistant.audio.media_stream] start media stream for: apple_music--4hmSTk5D://track/259593485
2025-02-25 09:10:06.934 VERBOSE (MainThread) [ffmpeg] Process ffmpeg started with PID 53
2025-02-25 09:10:06.934 VERBOSE (MainThread) [ffmpeg.53] started with args: -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp -decryption_key 8ef1c730c0003ec1d29427d69ffc5b70 -reconnect 1 -reconnect_delay_max 30 -reconnect_streamed 1 -reconnect_on_network_error 1 -reconnect_on_http_error 5xx,4xx -i <URL> -af aresample=resampler=soxr:precision=30:osr=48000 -acodec pcm_s16le -f s16le -ar 48000 -ac 2 -
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'https://aod-ssl.itunes.apple.com/itunes-assets/Music117/v4/62/14/a4/6214a47f-9c18-9cb7-ab04-822d818289b6/mzaf_A259593485.rmhq.aac.wa.mp4':
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] Metadata:
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] major_brand     : mp42
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] minor_version   : 1
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] compatible_brands: mp41mp42isomhlsf
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] creation_time   : 2017-06-19T13:42:23.000000Z
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] Duration: 00:10:39.08, start: 0.000000, bitrate: 265 kb/s
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] Stream #0:0[0x1](und): Audio: aac (LC) (mp4a / 0x6134706D), 44100 Hz, stereo, fltp, 261 kb/s (default)
2025-02-25 09:10:13.091 DEBUG (MainThread) [ffmpeg.53] Detected (input) content type: aac (aac)
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] Metadata:
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] creation_time   : 2017-06-19T13:42:23.000000Z
2025-02-25 09:10:13.091 VERBOSE (MainThread) [ffmpeg.53] handler_name    : Core Media Audio
2025-02-25 09:10:13.092 VERBOSE (MainThread) [ffmpeg.53] vendor_id       : [0][0][0][0]
2025-02-25 09:10:13.092 VERBOSE (MainThread) [ffmpeg.53] Side data:
2025-02-25 09:10:13.092 VERBOSE (MainThread) [ffmpeg.53] unknown side data type 24 (488 bytes)
2025-02-25 09:10:13.092 VERBOSE (MainThread) [ffmpeg.53] Stream mapping:
2025-02-25 09:10:13.092 VERBOSE (MainThread) [ffmpeg.53] Stream #0:0 -> #0:0 (aac (native) -> pcm_s16le (native))
2025-02-25 09:10:13.092 VERBOSE (MainThread) [ffmpeg.53] Press [q] to stop, [?] for help
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] Output #0, s16le, to 'pipe:':
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] Metadata:
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] major_brand     : mp42
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] minor_version   : 1
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] compatible_brands: mp41mp42isomhlsf
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] encoder         : Lavf60.16.100
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] Stream #0:0(und): Audio: pcm_s16le, 48000 Hz, stereo, s16, 1536 kb/s (default)
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] Metadata:
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] creation_time   : 2017-06-19T13:42:23.000000Z
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] handler_name    : Core Media Audio
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] vendor_id       : [0][0][0][0]
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] encoder         : Lavc60.31.102 pcm_s16le
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] Side data:
2025-02-25 09:10:13.096 VERBOSE (MainThread) [ffmpeg.53] unknown side data type 24 (488 bytes)
2025-02-25 09:10:13.146 VERBOSE (MainThread) [ffmpeg.52] Input #0, s16le, from 'fd:':
2025-02-25 09:10:13.146 VERBOSE (MainThread) [ffmpeg.52] Duration: N/A, bitrate: 1536 kb/s
2025-02-25 09:10:13.146 VERBOSE (MainThread) [ffmpeg.52] Stream #0:0: Audio: pcm_s16le, 48000 Hz, stereo, s16, 1536 kb/s
2025-02-25 09:10:13.147 VERBOSE (MainThread) [ffmpeg.52] Stream mapping:
2025-02-25 09:10:13.147 VERBOSE (MainThread) [ffmpeg.52] Stream #0:0 -> #0:0 (pcm_s16le (native) -> mp3 (libmp3lame))
2025-02-25 09:10:13.150 VERBOSE (MainThread) [ffmpeg.52] Output #0, mp3, to 'pipe:':
2025-02-25 09:10:13.151 VERBOSE (MainThread) [ffmpeg.52] Metadata:
2025-02-25 09:10:13.151 VERBOSE (MainThread) [ffmpeg.52] TSSE            : Lavf60.16.100
2025-02-25 09:10:13.151 VERBOSE (MainThread) [ffmpeg.52] Stream #0:0: Audio: mp3, 48000 Hz, stereo, fltp, 320 kb/s
2025-02-25 09:10:13.151 VERBOSE (MainThread) [ffmpeg.52] Metadata:
2025-02-25 09:10:13.151 VERBOSE (MainThread) [ffmpeg.52] encoder         : Lavc60.31.102 libmp3lame
2025-02-25 09:10:13.163 VERBOSE (MainThread) [ffmpeg.52] Process ffmpeg with PID 52 stopped with returncode 255
2025-02-25 09:10:13.167 VERBOSE (MainThread) [ffmpeg.53] Process ffmpeg with PID 53 stopped with returncode 255
2025-02-25 09:10:13.167 DEBUG (MainThread) [music_assistant.audio.media_stream] stream aborted (with code 255) for apple_music--4hmSTk5D://track/259593485 - seconds streamed: 4.0

[OzGav]

beta would be best (although will be be promoted to stable very soon) as there are heaps of improvements. Having said that the log may provide some useful clues

[johnboiles]

Ok! I switched to 2.4.0rc9.

[OzGav]

2.4.0 has been released.

[MarkHofmann11]

I didn't want to open a new issue in case this is the same thing. I have been seeing this around 30% of the time after upgrading from 2.3.3 to 2.4.2. This is using HA automations to play annoucements and occationally it won't resume what was originally playing with error code 255. These are local MP3 files.
2025-03-01 03:01:06.791 DEBUG (MainThread) [music_assistant.streams] Finished serving audio stream for Announcement http://192.168.0.14:8123/local/binary_sensor.front_door_is_closed.mp3 to Foyer Mini 2025-03-01 03:01:06.864 DEBUG (MainThread) [music_assistant.audio.media_stream] stream aborted (with code 255) for filesystem_local--e9Cyfvje://track/White_Noise_10hrs.mp3 - seconds streamed: 3.0 comment : encoder : Lavf61.7.100 Stream #0:0: Audio: pcm_f32le, 44100 Hz, stereo, flt, 2822 kb/s Metadata: encoder : Lavc61.19.100 pcm_f32le

[OzGav]

@MarkHofmann11 If you aren't sure where your query should go then first ask in Discord or the Q&A Discussion section of this repo. Your error is not the same as the OP. (Try the latest beta as part of your troubleshooting)

@johnboiles This will be closed soon assuming fixed

[johnboiles]

I didn't notice it happen again yet but it is intermittent so I'm hesitant to declare victory until it works for a week. Is there a patch you think that fixed it that I could review?

If @MarkHofmann11 is getting his ffmeg process killed prematurely by MA (returncode 255) it sounds like potentially the same issue to me.

@MarkHofmann11 are you using an ESPHome player?

[MarkHofmann11]

I'm using the native Chromecast players from MA inside of HA. I just changed the way it plays the file from "local filesystem" to http: (HA's internal web server) to see if it behaves differently and resumes consistantly.