Stops functioning after service call queuing issue

[crowbarsolutions]

System Health details

System Information

version	core-2024.4.3
installation_type	Home Assistant OS
dev	false
hassio	true
docker	true
user	root
virtualenv	false
python_version	3.12.2
os_name	Linux
os_version	6.6.25-haos
arch	x86_64
timezone	America/Edmonton
config_dir	/config

Home Assistant Community Store

GitHub API	ok
GitHub Content	ok
GitHub Web	ok
GitHub API Calls Remaining	5000
Installed Version	1.34.0
Stage	running
Available Repositories	1398
Downloaded Repositories	4

Home Assistant Cloud

logged_in	false
can_reach_cert_server	ok
can_reach_cloud_auth	ok
can_reach_cloud	ok

Home Assistant Supervisor

host_os	Home Assistant OS 12.2
update_channel	stable
supervisor_version	supervisor-2024.04.0
agent_version	1.6.0
docker_version	25.0.5
disk_total	30.8 GB
disk_used	4.0 GB
healthy	true
supported	true
board	ova
supervisor_api	ok
version_api	ok
installed_addons	Duck DNS (1.16.0), NGINX Home Assistant SSL proxy (3.9.0), File editor (5.8.0), Mosquitto broker (6.4.0), Zigbee2MQTT (1.36.1-1), Terminal & SSH (9.13.0), Ring-MQTT with Video Streaming (5.6.3)

Dashboards

dashboards	3
resources	0
views	1
mode	storage

Recorder

oldest_recorder_run	April 8, 2024 at 2:09 AM
current_recorder_run	April 16, 2024 at 5:02 PM
estimated_db_size	42.77 MiB
database_engine	sqlite
database_version	3.44.2

Checklist

• [X] I have enabled debug logging for my installation.
• [X] I have filled out the issue template to the best of my ability.
• [X] This issue only contains 1 issue (if you have multiple issues, open one issue for each issue).
• [X] This issue is not a duplicate issue of currently previous issues..

Describe the issue

I am using the latest beta v1.1.0-beta2

I have several automations running that make use of ChimeTTS. Some of them are set to run in parallel, and it is possible that multiple automations will make a call to Chime at the same time. As a result it is possible they will get queued. After a while it seems that Chime gets into a deadlock state where any new requests to the service are added to a queue (Adding service call to queue in the logs are added), and are never processed. Further calls to ChimeTTS just result in more calls being added to the queue according to the logs. It has been difficult to reproduce this.

When it does reach the deadlock state I can confirm that sending an MP3 to my speaker group still works fine, and making a call to my TTS service (microsoft) directly to play sound over my speakers also works correctly, it is just services through chime that stop processing requests. Reloading the Chime integration doesn't seem to fix it, I need to do a full restart of home assistant to get it out of this state. Only then will it return to working normally and playing sound over the speakers.

It might be related to caching, I have caching enabled for all my calls to the service, and when it happened this time, I changed one of my chime MP3's and ran the clear cache service. The next time I tried to call ChimeTTS it failed.

Reproduction steps

1. Use ChimeTTS in various automations, some set to run in parallel
2. At some point subsequent calls to the ChimeTTS service stop resulting in any sound being generated
3. The logs shows "Adding service call to queue"
4. Calls to the Media Player Service still work
5. Call to the TTS Service still work
6. A restart of HA is needed to fix the issue

Debug logs

2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say Called. Version v1.1.0-beta2 -----
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.queue_manager] Adding service call to queue
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] ----- General Parameters -----
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * entity_ids = ['media_player.announcement_speakers_group']
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * chime_path = custom_chime_path_3
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * cache = True
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * offset = -700.0
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * final_delay = 0.0
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * message = Upper Rear Door was left open
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * tts_speed = 100.0
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * tts_pitch = 0
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * announce = True
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * volume_level = -1
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * join_players = False
2024-04-17 14:41:31.315 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * unjoin_players = False
2024-04-17 14:41:31.316 DEBUG (MainThread) [custom_components.chime_tts] *** Checking Chime TTS audio cache ***
2024-04-17 14:41:31.322 DEBUG (MainThread) [custom_components.chime_tts] ...no cached audio found
2024-04-17 14:41:31.322 DEBUG (MainThread) [custom_components.chime_tts] - Retrieving audio from path: "/media/bong.mp3"...
2024-04-17 14:41:31.431 DEBUG (MainThread) [custom_components.chime_tts] ...audio retrieved. Duration: 3.291s
2024-04-17 14:41:31.432 DEBUG (MainThread) [custom_components.chime_tts] - Attempting to retrieve TTS audio from cache...
2024-04-17 14:41:31.434 DEBUG (MainThread) [custom_components.chime_tts] ...no cached TTS audio found
2024-04-17 14:41:31.435 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] - Using default TTS platform: 'microsoft'
2024-04-17 14:41:31.435 DEBUG (MainThread) [custom_components.chime_tts] - Generating new TTS audio with parameters:
2024-04-17 14:41:31.435 DEBUG (MainThread) [custom_components.chime_tts] * tts_platform = 'microsoft'
2024-04-17 14:41:31.435 DEBUG (MainThread) [custom_components.chime_tts] * message = 'Upper Rear Door was left open'
2024-04-17 14:41:31.435 DEBUG (MainThread) [custom_components.chime_tts] * cache = True
2024-04-17 14:41:31.435 DEBUG (MainThread) [custom_components.chime_tts] * language = None
2024-04-17 14:41:31.435 DEBUG (MainThread) [custom_components.chime_tts] * options = {}
2024-04-17 14:41:32.137 DEBUG (MainThread) [custom_components.chime_tts] ...TTS audio generated in 700.0ms
2024-04-17 14:41:32.138 DEBUG (MainThread) [custom_components.chime_tts] - Saving generated TTS audio to cache...
2024-04-17 14:41:32.212 DEBUG (MainThread) [custom_components.chime_tts.helpers.filesystem] - File saved to path: /media/sounds/temp/chime_tts/sketoz3p.mp3
2024-04-17 14:41:32.213 DEBUG (MainThread) [custom_components.chime_tts] - Saving data to chime_tts storage:
2024-04-17 14:41:32.213 DEBUG (MainThread) [custom_components.chime_tts] - key: "69cc0da640b971191674070309573098b07656fbe2ea2fa62d1b7e82456cd7f4"
2024-04-17 14:41:32.213 DEBUG (MainThread) [custom_components.chime_tts] - value: "{'local_path': '/media/sounds/temp/chime_tts/sketoz3p.mp3', 'audio_duration': 2.832}"
2024-04-17 14:41:32.214 DEBUG (MainThread) [custom_components.chime_tts] ...TTS audio saved to cache
2024-04-17 14:41:32.220 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] Performing overlay of -700.0ms
2024-04-17 14:41:32.229 DEBUG (MainThread) [custom_components.chime_tts] - Saving mp3 file to folder: /media/sounds/temp/chime_tts/...
2024-04-17 14:41:32.375 DEBUG (MainThread) [custom_components.chime_tts.helpers.filesystem] - File saved to path: /media/sounds/temp/chime_tts/anbq1khi.mp3
2024-04-17 14:41:32.488 DEBUG (MainThread) [custom_components.chime_tts] - Saving data to chime_tts storage:
2024-04-17 14:41:32.488 DEBUG (MainThread) [custom_components.chime_tts] - key: "bf03d9f0408b1d39335c8494148b8ac577599fd8b37c65e0fad248361f4ae5fd"
2024-04-17 14:41:32.488 DEBUG (MainThread) [custom_components.chime_tts] - value: "{'local_path': '/media/sounds/temp/chime_tts/anbq1khi.mp3', 'audio_duration': 5.423}"
2024-04-17 14:41:32.489 DEBUG (MainThread) [custom_components.chime_tts] - Chime TTS audio generated:
2024-04-17 14:41:32.489 DEBUG (MainThread) [custom_components.chime_tts] - audio_duration = 5.423
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] - local_path = "/media/sounds/temp/chime_tts/anbq1khi.mp3"
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] - public_path = None
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] - media_content_id = "media-source://media_source/local/sounds/temp/chime_tts/anbq1khi.mp3"
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] *** Pre-Playback Actions ***
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] *** Chime TTS playback ***
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] 1 Standard media player detected:
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] - media_player.announcement_speakers_group
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] Calling media_player.play_media with data:
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] - media_content_type: music
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] - media_content_id: media-source://media_source/local/sounds/temp/chime_tts/anbq1khi.mp3
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] - announce: True
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] - entity_id: ['media_player.announcement_speakers_group']
2024-04-17 14:41:32.490 DEBUG (MainThread) [custom_components.chime_tts] - Waiting 5.423s for audio playback to complete...
2024-04-17 14:41:37.916 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] - Waiting until 1 media_player isn't playing...
2024-04-17 14:41:38.318 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] ✔ media_player.announcement_speakers_group
2024-04-17 14:41:38.318 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say Completed in 7.0 s -----
2024-04-17 14:42:08.319 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say Called. Version v1.1.0-beta2 -----
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.queue_manager] Adding service call to queue
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] ----- General Parameters -----
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * entity_ids = ['media_player.announcement_speakers_group']
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * chime_path = custom_chime_path_3
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * cache = True
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * offset = -700.0
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * final_delay = 0.0
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * message = Upper Rear Door was left open
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * tts_speed = 100.0
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * tts_pitch = 0
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * announce = True
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * volume_level = -1
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * join_players = False
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * unjoin_players = False
2024-04-17 14:42:08.320 DEBUG (MainThread) [custom_components.chime_tts] *** Checking Chime TTS audio cache ***
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] Cached audio found:
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] - local_path = "/media/sounds/temp/chime_tts/anbq1khi.mp3"
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] - audio_duration = 5.423
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] - public_path = None
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] - media_content_id = "media-source://media_source/local/sounds/temp/chime_tts/anbq1khi.mp3"
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] *** Pre-Playback Actions ***
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] *** Chime TTS playback ***
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] 1 Standard media player detected:
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] - media_player.announcement_speakers_group
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] Calling media_player.play_media with data:
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] - media_content_type: music
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] - media_content_id: media-source://media_source/local/sounds/temp/chime_tts/anbq1khi.mp3
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] - announce: True
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] - entity_id: ['media_player.announcement_speakers_group']
2024-04-17 14:42:08.323 DEBUG (MainThread) [custom_components.chime_tts] - Waiting 5.423s for audio playback to complete...
2024-04-17 14:42:13.749 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] - Waiting until 1 media_player isn't playing...
2024-04-17 14:42:14.150 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] ✔ media_player.announcement_speakers_group
2024-04-17 14:42:14.151 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say Completed in 5.83 s -----
2024-04-17 14:42:20.811 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say Called. Version v1.1.0-beta2 -----
2024-04-17 14:42:20.812 DEBUG (MainThread) [custom_components.chime_tts.queue_manager] Adding service call to queue
2024-04-17 14:42:36.799 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say Called. Version v1.1.0-beta2 -----
2024-04-17 14:42:36.799 DEBUG (MainThread) [custom_components.chime_tts.queue_manager] Adding service call to queue
2024-04-17 14:42:55.361 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say Called. Version v1.1.0-beta2 -----
2024-04-17 14:42:55.361 DEBUG (MainThread) [custom_components.chime_tts.queue_manager] Adding service call to queue

Diagnostics dump

No response