TTS Continuously repeats last announcement when using Music Assistant and the Sonos S1 Provider and Speaker.

[mikesnook]

Music Assistant Server Version: 2.7.3
Openai TTS Integration Version: 3.6

Using the following to generate the TTS output in HA:

action: openai_tts.say
target:
  entity_id: media_player.basement_ma
data:
  chime: true
  tts_entity: tts.openai_tts_test_2
  message: this is a test
  chime_sound: beep.mp3
  volume: 0.5

If nothing is already playing on the Sonos speaker the TTS "this is a test" continuously repeats until i stop it manually, however if there is already music playing on the Sonos speaker the music correctly resumes after the TTS without any repeats.

TTS when no music playing:

2026-01-14 18:17:00.319 DEBUG (MainThread) [custom_components.openai_tts] Service call data: {'chime': True, 'tts_entity': 'tts.openai_tts_test_2', 'message': 'this is a test', 'chime_sound': 'beep.mp3', 'volume': 0.5, 'entity_id': ['media_player.basement_ma'], 'language': 'en', 'normalize_audio': False}
2026-01-14 18:17:00.319 DEBUG (MainThread) [custom_components.openai_tts] Service call target: None
2026-01-14 18:17:00.319 DEBUG (MainThread) [custom_components.openai_tts] Found entity_id in data: ['media_player.basement_ma']
2026-01-14 18:17:00.319 DEBUG (MainThread) [custom_components.openai_tts] Target: {'entity_id': ['media_player.basement_ma']}
2026-01-14 18:17:00.319 DEBUG (MainThread) [custom_components.openai_tts] Added entity_ids from target: ['media_player.basement_ma']
2026-01-14 18:17:00.319 DEBUG (MainThread) [custom_components.openai_tts] Final entities from target: ['media_player.basement_ma']
2026-01-14 18:17:00.319 DEBUG (MainThread) [custom_components.openai_tts] Media players from target data: ['media_player.basement_ma']
2026-01-14 18:17:00.319 DEBUG (MainThread) [custom_components.openai_tts] Found entity defaults from subentry: {'chime': True, 'chime_sound': 'beep.mp3', 'normalize_audio': False}
2026-01-14 18:17:00.319 DEBUG (MainThread) [custom_components.openai_tts] Calling announce with: tts_entity=tts.openai_tts_test_2, media_players=['media_player.basement_ma'], message=this is a test, pause_playback=None
2026-01-14 18:17:00.319 INFO (MainThread) [custom_components.openai_tts.volume_restore] Playing TTS on 1 players with volume control
2026-01-14 18:17:00.319 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] TTS entity tts.openai_tts_test_2 state: 2026-01-14T17:55:14.704100+00:00
2026-01-14 18:17:00.320 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Generating TTS audio first (without players)
2026-01-14 18:17:00.320 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] TTS entity tts.openai_tts_test_2 found, state: 2026-01-14T17:55:14.704100+00:00
2026-01-14 18:17:00.321 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Preparing 1 players, target_volume=None
2026-01-14 18:17:00.325 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Recorded volume 0.49 for media_player.basement_ma (state: idle)
2026-01-14 18:17:00.325 INFO (MainThread) [custom_components.openai_tts.volume_restore] Player preparation complete. Original volumes: {'media_player.basement_ma': 0.49}
2026-01-14 18:17:00.325 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Pre-speak duration: 4560 ms, timestamp: 2026-01-14 22:57:48.623279+00:00
2026-01-14 18:17:00.325 INFO (MainThread) [custom_components.openai_tts.volume_restore] Setting volume BEFORE speak (for streaming)
2026-01-14 18:17:00.325 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Setting volume for media_player.basement_ma (default): 0.49 -> 0.50 (delay: 500ms)
2026-01-14 18:17:00.326 DEBUG (MainThread) [custom_components.openai_tts.utils] Setting volume for media_player.basement_ma from 0.49 to 0.50
2026-01-14 18:17:00.754 DEBUG (MainThread) [custom_components.openai_tts.utils] Successfully set volume for media_player.basement_ma to 0.50 (actual: 0.50)
2026-01-14 18:17:00.757 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for voice from subentry data: af_sky (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.757 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for model from subentry data: tts-1 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.757 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for speed from subentry data: 1.0 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.757 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for chime from subentry data: True (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.757 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for chime_sound from subentry data: beep.mp3 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.757 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for normalize_audio from subentry data: False (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.760 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for voice from subentry data: af_sky (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.760 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for model from subentry data: tts-1 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.760 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for speed from subentry data: 1.0 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.760 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for chime from subentry data: True (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.760 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for chime_sound from subentry data: beep.mp3 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:00.760 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for normalize_audio from subentry data: False (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:17:15.629 INFO (MainThread) [custom_components.openai_tts.volume_restore] TTS speak service call completed in 14875 ms
2026-01-14 18:17:15.629 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Non-streaming detected - playback starts after speak returns
2026-01-14 18:17:15.629 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:15.629 INFO (MainThread) [custom_components.openai_tts.volume_restore] Engine finished - playback starts NOW (chime/normalize mode)
2026-01-14 18:17:15.730 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:15.831 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:15.931 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:16.032 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:16.138 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:16.239 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:16.340 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:16.441 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:16.542 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:16.643 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:16.745 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:16.846 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:16.947 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:17.054 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:17.160 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:17.261 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:17.361 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:17.462 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:17.563 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:17.665 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:17.765 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:17.866 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:17.967 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:18.068 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:18.169 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:18.271 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:18.372 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:18.473 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:18.574 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:18.674 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:17:18.674 WARNING (MainThread) [custom_components.openai_tts.volume_restore] Using fallback duration: 10000 ms
2026-01-14 18:17:18.674 INFO (MainThread) [custom_components.openai_tts.volume_restore] TTS: 3044 ms elapsed, 6956 ms remaining of 10000 ms total
2026-01-14 18:17:18.674 INFO (MainThread) [custom_components.openai_tts.volume_restore] === STARTING PARALLEL RESTORATION at 19234.534 ===
2026-01-14 18:17:18.674 INFO (MainThread) [custom_components.openai_tts.volume_restore] Duration: 6956 ms, Speakers: 1
2026-01-14 18:17:18.675 INFO (MainThread) [custom_components.openai_tts.volume_restore] Creating task for media_player.basement_ma: duration=6956, buffer=300, total_wait=7256 ms
2026-01-14 18:17:18.675 INFO (MainThread) [custom_components.openai_tts.volume_restore] Task created for media_player.basement_ma at 19234.534
2026-01-14 18:17:18.675 INFO (MainThread) [custom_components.openai_tts.volume_restore] media_player.basement_ma: STARTING wait - 6956 ms (duration) + 300 ms (buffer) = 7.3 seconds
2026-01-14 18:17:25.931 INFO (MainThread) [custom_components.openai_tts.volume_restore] media_player.basement_ma: FINISHED wait after 7256 ms, now restoring volume
2026-01-14 18:17:25.931 INFO (MainThread) [custom_components.openai_tts.volume_restore] Restoring volume for media_player.basement_ma: 0.50 -> 0.49 (diff: 0.01)
2026-01-14 18:17:25.931 DEBUG (MainThread) [custom_components.openai_tts.utils] Setting volume for media_player.basement_ma from 0.50 to 0.49
2026-01-14 18:17:26.260 DEBUG (MainThread) [custom_components.openai_tts.utils] Successfully set volume for media_player.basement_ma to 0.49 (actual: 0.49)
2026-01-14 18:17:26.260 INFO (MainThread) [custom_components.openai_tts.volume_restore] media_player.basement_ma: Volume restore completed (success=True)
2026-01-14 18:17:26.261 INFO (MainThread) [custom_components.openai_tts.volume_restore] Successfully restored 1 speakers

TTS when music IS playing:

2026-01-14 18:19:38.862 DEBUG (MainThread) [custom_components.openai_tts] Service call data: {'chime': True, 'tts_entity': 'tts.openai_tts_test_2', 'message': 'this is a test', 'chime_sound': 'beep.mp3', 'volume': 0.5, 'entity_id': ['media_player.basement_ma'], 'language': 'en', 'normalize_audio': False}
2026-01-14 18:19:38.862 DEBUG (MainThread) [custom_components.openai_tts] Service call target: None
2026-01-14 18:19:38.862 DEBUG (MainThread) [custom_components.openai_tts] Found entity_id in data: ['media_player.basement_ma']
2026-01-14 18:19:38.862 DEBUG (MainThread) [custom_components.openai_tts] Target: {'entity_id': ['media_player.basement_ma']}
2026-01-14 18:19:38.862 DEBUG (MainThread) [custom_components.openai_tts] Added entity_ids from target: ['media_player.basement_ma']
2026-01-14 18:19:38.862 DEBUG (MainThread) [custom_components.openai_tts] Final entities from target: ['media_player.basement_ma']
2026-01-14 18:19:38.862 DEBUG (MainThread) [custom_components.openai_tts] Media players from target data: ['media_player.basement_ma']
2026-01-14 18:19:38.863 DEBUG (MainThread) [custom_components.openai_tts] Found entity defaults from subentry: {'chime': True, 'chime_sound': 'beep.mp3', 'normalize_audio': False}
2026-01-14 18:19:38.863 DEBUG (MainThread) [custom_components.openai_tts] Calling announce with: tts_entity=tts.openai_tts_test_2, media_players=['media_player.basement_ma'], message=this is a test, pause_playback=None
2026-01-14 18:19:38.863 INFO (MainThread) [custom_components.openai_tts.volume_restore] Playing TTS on 1 players with volume control
2026-01-14 18:19:38.863 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] TTS entity tts.openai_tts_test_2 state: 2026-01-14T17:55:14.704100+00:00
2026-01-14 18:19:38.863 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Generating TTS audio first (without players)
2026-01-14 18:19:38.863 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] TTS entity tts.openai_tts_test_2 found, state: 2026-01-14T17:55:14.704100+00:00
2026-01-14 18:19:38.863 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Preparing 1 players, target_volume=None
2026-01-14 18:19:38.863 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Recorded volume 0.49 for media_player.basement_ma (state: playing)
2026-01-14 18:19:38.863 INFO (MainThread) [custom_components.openai_tts.volume_restore] Player preparation complete. Original volumes: {'media_player.basement_ma': 0.49}
2026-01-14 18:19:38.863 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Pre-speak duration: 4560 ms, timestamp: 2026-01-14 22:57:48.623279+00:00
2026-01-14 18:19:38.863 INFO (MainThread) [custom_components.openai_tts.volume_restore] Setting volume BEFORE speak (for streaming)
2026-01-14 18:19:38.864 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Setting volume for media_player.basement_ma (default): 0.49 -> 0.50 (delay: 500ms)
2026-01-14 18:19:38.864 DEBUG (MainThread) [custom_components.openai_tts.utils] Setting volume for media_player.basement_ma from 0.49 to 0.50
2026-01-14 18:19:39.192 DEBUG (MainThread) [custom_components.openai_tts.utils] Successfully set volume for media_player.basement_ma to 0.50 (actual: 0.50)
2026-01-14 18:19:39.195 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for voice from subentry data: af_sky (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.195 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for model from subentry data: tts-1 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.195 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for speed from subentry data: 1.0 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.195 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for chime from subentry data: True (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.195 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for chime_sound from subentry data: beep.mp3 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.195 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for normalize_audio from subentry data: False (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.199 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for voice from subentry data: af_sky (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.199 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for model from subentry data: tts-1 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.199 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for speed from subentry data: 1.0 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.199 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for chime from subentry data: True (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.199 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for chime_sound from subentry data: beep.mp3 (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:39.199 DEBUG (MainThread) [custom_components.openai_tts.tts] Getting config value for normalize_audio from subentry data: False (entry_id: 01K5FWXC7NPQCNSTQD4PG8NBTG)
2026-01-14 18:19:56.730 INFO (MainThread) [custom_components.openai_tts.volume_restore] TTS speak service call completed in 17538 ms
2026-01-14 18:19:56.730 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] Non-streaming detected - playback starts after speak returns
2026-01-14 18:19:56.730 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:56.730 INFO (MainThread) [custom_components.openai_tts.volume_restore] Engine finished - playback starts NOW (chime/normalize mode)
2026-01-14 18:19:56.831 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:56.932 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:57.032 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:57.133 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:57.234 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:57.334 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:57.435 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:57.535 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:57.636 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:57.741 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:57.842 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:57.951 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:58.051 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:58.153 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:58.254 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:58.354 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:58.490 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:58.590 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:58.691 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:58.791 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:58.891 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:58.994 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:59.094 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:59.196 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:59.298 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:59.402 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:59.515 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:59.616 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:59.717 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:59.817 DEBUG (MainThread) [custom_components.openai_tts.volume_restore] No cached duration found for message hash: 54b0c58c7ce9f2a8 (cache has 100 entries)
2026-01-14 18:19:59.818 WARNING (MainThread) [custom_components.openai_tts.volume_restore] Using fallback duration: 10000 ms
2026-01-14 18:19:59.818 INFO (MainThread) [custom_components.openai_tts.volume_restore] TTS: 3087 ms elapsed, 6913 ms remaining of 10000 ms total
2026-01-14 18:19:59.818 INFO (MainThread) [custom_components.openai_tts.volume_restore] === STARTING PARALLEL RESTORATION at 19395.677 ===
2026-01-14 18:19:59.818 INFO (MainThread) [custom_components.openai_tts.volume_restore] Duration: 6913 ms, Speakers: 1
2026-01-14 18:19:59.818 INFO (MainThread) [custom_components.openai_tts.volume_restore] Creating task for media_player.basement_ma: duration=6913, buffer=300, total_wait=7213 ms
2026-01-14 18:19:59.818 INFO (MainThread) [custom_components.openai_tts.volume_restore] Task created for media_player.basement_ma at 19395.677
2026-01-14 18:19:59.818 INFO (MainThread) [custom_components.openai_tts.volume_restore] media_player.basement_ma: STARTING wait - 6913 ms (duration) + 300 ms (buffer) = 7.2 seconds
2026-01-14 18:20:07.032 INFO (MainThread) [custom_components.openai_tts.volume_restore] media_player.basement_ma: FINISHED wait after 7214 ms, now restoring volume
2026-01-14 18:20:07.032 INFO (MainThread) [custom_components.openai_tts.volume_restore] Restoring volume for media_player.basement_ma: 0.50 -> 0.49 (diff: 0.01)
2026-01-14 18:20:07.032 DEBUG (MainThread) [custom_components.openai_tts.utils] Setting volume for media_player.basement_ma from 0.50 to 0.49
2026-01-14 18:20:07.414 DEBUG (MainThread) [custom_components.openai_tts.utils] Successfully set volume for media_player.basement_ma to 0.49 (actual: 0.49)
2026-01-14 18:20:07.414 INFO (MainThread) [custom_components.openai_tts.volume_restore] media_player.basement_ma: Volume restore completed (success=True)
2026-01-14 18:20:07.417 INFO (MainThread) [custom_components.openai_tts.volume_restore] Successfully restored 1 speakers

Thank you for the great integration!

[sfortis]

I investigated this and the openai_tts integration is completing successfully. The logs show volume restoration working correctly and the TTS service call finishing as expected. The issue appears to be on the Music Assistant side. Looking at the MA logs there are multiple "Queue session_id is None" errors and "Player disconnected prematurely from stream" warnings which suggest MA is having trouble managing the queue state after the announcement completes. When the speaker is idle (no queue), MA seems to loop the announcement instead of properly stopping. I recommend opening an issue with Music Assistant as this appears to be related to how their Sonos S1 provider handles announcements on idle speakers.