Closed crowbarsolutions closed 5 months ago
Not sure if this is related or a separate issue, but it appears sometimes using ChimeTTS it will result in one or more of the speakers in my speaker group getting muted, here is a log of that happening below. Am I misusing ChimeTTS in some way to cause this condition? Let me know if I should put this in a seperate issue.
2024-04-17 15:10:00.808 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say Called. Version v1.1.0-beta2 -----
2024-04-17 15:10:00.808 DEBUG (MainThread) [custom_components.chime_tts.queue_manager] Adding service call to queue
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] ----- General Parameters -----
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * entity_ids = ['media_player.announcement_speakers_group']
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * chime_path = custom_chime_path_3
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * cache = True
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * offset = -2000.0
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * final_delay = 0.0
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * message = Front Door was left open
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * tts_speed = 100.0
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * tts_pitch = 0
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * announce = True
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * volume_level = -1
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * join_players = False
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * unjoin_players = False
2024-04-17 15:10:00.809 DEBUG (MainThread) [custom_components.chime_tts] *** Checking Chime TTS audio cache ***
2024-04-17 15:10:00.811 DEBUG (MainThread) [custom_components.chime_tts] Cached audio found:
2024-04-17 15:10:00.811 DEBUG (MainThread) [custom_components.chime_tts] - local_path = "/media/sounds/temp/chime_tts/hcxiz618.mp3"
2024-04-17 15:10:00.811 DEBUG (MainThread) [custom_components.chime_tts] - audio_duration = 3.835
2024-04-17 15:10:00.811 DEBUG (MainThread) [custom_components.chime_tts] - public_path = None
2024-04-17 15:10:00.811 DEBUG (MainThread) [custom_components.chime_tts] - media_content_id = "media-source://media_source/local/sounds/temp/chime_tts/hcxiz618.mp3"
2024-04-17 15:10:00.811 DEBUG (MainThread) [custom_components.chime_tts] *** Pre-Playback Actions ***
2024-04-17 15:10:00.811 DEBUG (MainThread) [custom_components.chime_tts] - Fading out media_players currently playing
2024-04-17 15:10:01.135 DEBUG (MainThread) [custom_components.chime_tts] - Pausing 1 media_player
2024-04-17 15:10:01.135 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] - Waiting until 1 media_player is paused...
2024-04-17 15:10:01.337 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] ✔ media_player.announcement_speakers_group
2024-04-17 15:10:01.338 DEBUG (MainThread) [custom_components.chime_tts] *** Chime TTS playback ***
2024-04-17 15:10:01.338 DEBUG (MainThread) [custom_components.chime_tts] 1 Standard media player detected:
2024-04-17 15:10:01.338 DEBUG (MainThread) [custom_components.chime_tts] - media_player.announcement_speakers_group
2024-04-17 15:10:01.338 DEBUG (MainThread) [custom_components.chime_tts] Calling media_player.play_media with data:
2024-04-17 15:10:01.338 DEBUG (MainThread) [custom_components.chime_tts] - media_content_type: music
2024-04-17 15:10:01.338 DEBUG (MainThread) [custom_components.chime_tts] - media_content_id: media-source://media_source/local/sounds/temp/chime_tts/hcxiz618.mp3
2024-04-17 15:10:01.338 DEBUG (MainThread) [custom_components.chime_tts] - announce: True
2024-04-17 15:10:01.338 DEBUG (MainThread) [custom_components.chime_tts] - entity_id: ['media_player.announcement_speakers_group']
2024-04-17 15:10:01.338 DEBUG (MainThread) [custom_components.chime_tts] - Waiting 3.835s for audio playback to complete...
2024-04-17 15:10:05.174 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] - Waiting until 1 media_player isn't playing...
2024-04-17 15:10:05.575 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] ✔ media_player.announcement_speakers_group
2024-04-17 15:10:05.576 DEBUG (MainThread) [custom_components.chime_tts] *** Post-Playback Actions ***
2024-04-17 15:10:05.576 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] - Waiting until 1 media_player is paused...
2024-04-17 15:10:10.591 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] 𝘅 media_player.announcement_speakers_group - Timed out
2024-04-17 15:10:10.591 WARNING (MainThread) [custom_components.chime_tts] Timed out waiting for 1 media_player to pause
2024-04-17 15:10:10.591 DEBUG (MainThread) [custom_components.chime_tts] - Setting volume to 0
2024-04-17 15:10:10.592 DEBUG (MainThread) [custom_components.chime_tts] - Resuming 1 media_player
2024-04-17 15:10:13.612 WARNING (MainThread) [custom_components.chime_tts] Failed to resume playback on media_player.announcement_speakers_group
2024-04-17 15:10:13.612 DEBUG (MainThread) [custom_components.chime_tts.helpers.media_player] - Fading out media_player.announcement_speakers_group's volume from 0.0 to -1.0
2024-04-17 15:10:13.938 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say Completed in 13.13 s -----
Using beta v1.1.0-beta2
I'm having the same issue, although it is not running in parallel (I don't think). I've got a main call that (almost) everything goes through, which queues up each request.
Either way, I also see the same issue.
This has happened at least 3 times now with beta2. And restarting fixes it.
I just updated to beta4 and will let you know if this happens again.
edit: yes, it's still happening with beta4
024-04-21 20:23:58.972 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say URL Called. Version v1.1.0-beta2 -----
2024-04-21 20:23:58.972 DEBUG (MainThread) [custom_components.chime_tts.queue_manager] Adding service call to queue
2024-04-21 20:23:58.979 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] ----- General Parameters -----
2024-04-21 20:23:58.979 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * entity_ids = []
2024-04-21 20:23:58.979 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * cache = True
2024-04-21 20:23:58.979 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * offset = 450.0
2024-04-21 20:23:58.980 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * final_delay = 0.0
2024-04-21 20:23:58.980 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * message = [{'chime': 'media/notify.mp3', 'audio_conversion': '-filter:a volume=0.8'}, {'tts': 'Front Door was unlocked by Home Assistant', 'offset': -800}]
2024-04-21 20:23:58.980 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * tts_platform = tts.openai_tts
2024-04-21 20:23:58.980 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * tts_speed = 100.0
2024-04-21 20:23:58.980 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * tts_pitch = 0
2024-04-21 20:23:58.980 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * announce = False
2024-04-21 20:23:58.980 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * volume_level = -1
2024-04-21 20:23:58.980 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * join_players = False
2024-04-21 20:23:58.980 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] * unjoin_players = False
2024-04-21 20:23:58.980 DEBUG (MainThread) [custom_components.chime_tts] *** Checking Chime TTS audio cache ***
2024-04-21 20:23:58.993 WARNING (MainThread) [custom_components.chime_tts.helpers.filesystem] Unable to create public URL - File: '/media/chime_tts/6g6fk3bg.mp3' is outside the public folder.
2024-04-21 20:23:58.993 DEBUG (MainThread) [custom_components.chime_tts] ...no cached audio found
2024-04-21 20:23:58.994 DEBUG (MainThread) [custom_components.chime_tts] - Retrieving audio from path: "/media/notify.mp3"...
2024-04-21 20:23:58.994 DEBUG (MainThread) [custom_components.chime_tts] - Performing FFmpeg audio conversion of audio file...
2024-04-21 20:23:58.994 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] Converting audio: "ffmpeg -i /media/notify.mp3 -filter:a volume=0.8 /media/notify_converted.mp3"
2024-04-21 20:23:59.221 DEBUG (MainThread) [custom_components.chime_tts] ...audio retrieved. Duration: 1.536s
2024-04-21 20:23:59.221 DEBUG (MainThread) [custom_components.chime_tts] - Attempting to retrieve TTS audio from cache...
2024-04-21 20:23:59.229 DEBUG (MainThread) [custom_components.chime_tts] - Retrieving audio from path: "/media/sounds/temp/chime_tts/t1t_3_2w.mp3"...
2024-04-21 20:23:59.467 DEBUG (MainThread) [custom_components.chime_tts] ...audio retrieved. Duration: 2.52s
2024-04-21 20:23:59.468 DEBUG (MainThread) [custom_components.chime_tts.helpers.helpers] Performing overlay of -800.0ms
2024-04-21 20:23:59.469 DEBUG (MainThread) [custom_components.chime_tts] - Saving mp3 file to folder: /media/chime_tts/...
2024-04-21 20:23:59.607 DEBUG (MainThread) [custom_components.chime_tts.helpers.filesystem] - File saved to path: /media/chime_tts/g0ycoqoc.mp3
2024-04-21 20:23:59.924 DEBUG (MainThread) [custom_components.chime_tts] - Saving data to chime_tts storage:
2024-04-21 20:23:59.924 DEBUG (MainThread) [custom_components.chime_tts] - key: "6e6997b39e01ce52ae4890da74e55997d61deaddf1743de23b06697dd46b080f"
2024-04-21 20:23:59.924 DEBUG (MainThread) [custom_components.chime_tts] - value: "{'public_path': '/media/chime_tts/g0ycoqoc.mp3', 'audio_duration': 3.256, 'local_path': None}"
2024-04-21 20:23:59.965 WARNING (MainThread) [custom_components.chime_tts.helpers.filesystem] Unable to create public URL - File: '/media/chime_tts/g0ycoqoc.mp3' is outside the public folder.
2024-04-21 20:23:59.965 DEBUG (MainThread) [custom_components.chime_tts] - Chime TTS audio generated:
2024-04-21 20:23:59.966 DEBUG (MainThread) [custom_components.chime_tts] - audio_duration = 3.256
2024-04-21 20:23:59.966 DEBUG (MainThread) [custom_components.chime_tts] - local_path = None
2024-04-21 20:23:59.966 DEBUG (MainThread) [custom_components.chime_tts] - public_path = None
2024-04-21 20:23:59.966 DEBUG (MainThread) [custom_components.chime_tts] - media_content_id = "media-source://media_source/local/chime_tts/g0ycoqoc.mp3"
2024-04-21 20:23:59.966 DEBUG (MainThread) [custom_components.chime_tts] Final URL = None
2024-04-21 20:23:59.966 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say URL Completed in 990.0 ms -----
2024-04-21 20:23:59.979 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say URL Called. Version v1.1.0-beta2 -----
2024-04-21 20:23:59.979 DEBUG (MainThread) [custom_components.chime_tts.queue_manager] Adding service call to queue
2024-04-21 20:26:07.764 DEBUG (MainThread) [custom_components.chime_tts] ----- Chime TTS Say URL Called. Version v1.1.0-beta2 -----
2024-04-21 20:26:07.764 DEBUG (MainThread) [custom_components.chime_tts.queue_manager] Adding service call to queue
Possibly the one I recently filed (https://github.com/nimroddolev/chime_tts/issues/137) is duplicate/related to this one based on the 'adding service call to queue'
Some more details. I'm finding that whenever you do anything that requires service calls for ChimeTTS to get queued up, problems can happen. Here are some more errors from the HA System Logs:
/usr/local/lib/python3.12/asyncio/base_events.py:1973: RuntimeWarning: coroutine 'ChimeTTSQueueManager.queue_processor' was never awaited handle = self._ready.popleft()
Detected blocking call to import_module with args ('custom_components.chime_tts',) in /usr/src/homeassistant/homeassistant/loader.py, line 1046: ComponentProtocol, importlib.import_module(self.pkg_path) inside the event loop
I made a small improvement in v1.1.0-beta10 which I hope fixes the issue. I cannot reproduce the bug, so if anyone here has the issue in this latest beta, please send me the steps to reproduce.
I have included fixes for this issue in the latest stable release, v1.1.0. I would kindly ask if you could please upgrade to the new version and let me know if the issue is resolved.
I am closing the issue. Please reopen if the issue persists.
System Health details
System Information
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 | 4Home Assistant Cloud
logged_in | false -- | -- can_reach_cert_server | ok can_reach_cloud_auth | ok can_reach_cloud | okHome 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 | storageRecorder
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.2Checklist
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
Debug logs
Diagnostics dump
No response