"The announcement pipeline's file reader encountered an error"

[RobMeades]

I have performed a trial installation of TTMG from scratch today, using OpenAI TTS, but am getting about a 50% failure rate in the playback part: the HAVPE log says "[E][speaker_media_player:334]: The announcement pipeline's file reader encountered an error".

The failure doesn't seem to be related to the query or the response/length, just happens randomly when using the same query each time. For instance, find below logs of a success case followed by a fail case of the query "Please count from 1 to 10" (TTMG is on 10.10.1.11, HAVPE is on 10.10.1.25). Looks as though the response audio is simply not arriving at the HAVPE (HAVPE reporting signal strength -40 dBm, shouldn't be an issue as it is about 3 metres away from the WiFi access point).

Any suggestions as to how I might narrow down what's going on? 10.10.1.11 is a desktop Ubuntu machine with wired Ethernet.

EDIT: I am also running the non-TTMG HAVPE so it seems likely that this the issue is somehow TTMG-linked.

HAVPE side:

[15:36:20][D][micro_wake_word:355]: Detected 'Okay Nabu' with sliding average probability is 0.89 and max probability is 0.98
[15:36:20][D][media_player:073]: 'Home Assistant Voice Streaming' - Setting
[15:36:20][D][media_player:077]:   Command: STOP
[15:36:20][D][media_player:086]:  Announcement: yes
[15:36:20][D][ring_buffer:034][ann_read]: Created ring buffer with size 1000000
[15:36:20][D][speaker_media_player:420]: State changed to ANNOUNCING
[15:36:20][D][speaker_media_player.pipeline:114]: Reading FLAC file type
[15:36:20][D][speaker_media_player.pipeline:124]: Decoded audio has 1 channels, 48000 Hz sample rate, and 16 bits per sample
[15:36:20][D][ring_buffer:034]: Created ring buffer with size 9600
[15:36:20][D][speaker_mixer:306]: Starting speaker mixer
[15:36:20][D][speaker_mixer:314]: Started speaker mixer
[15:36:20][D][voice_assistant:515]: State changed from IDLE to START_MICROPHONE
[15:36:20][D][voice_assistant:522]: Desired state set to START_PIPELINE
[15:36:20][D][voice_assistant:225]: Starting Microphone
[15:36:20][D][voice_assistant:515]: State changed from START_MICROPHONE to STARTING_MICROPHONE
[15:36:20][D][voice_assistant:515]: State changed from STARTING_MICROPHONE to START_PIPELINE
[15:36:20][D][voice_assistant:280]: Requesting start...
[15:36:20][D][voice_assistant:515]: State changed from START_PIPELINE to STARTING_PIPELINE
[15:36:20][D][voice_assistant:537]: Client started, streaming microphone
[15:36:20][D][voice_assistant:515]: State changed from STARTING_PIPELINE to STREAMING_MICROPHONE
[15:36:20][D][voice_assistant:522]: Desired state set to STREAMING_MICROPHONE
[15:36:21][D][voice_assistant:641]: Event Type: 1
[15:36:21][D][voice_assistant:644]: Assist Pipeline running
[15:36:21][D][voice_assistant:641]: Event Type: 3
[15:36:21][D][voice_assistant:655]: STT started
[15:36:21][D][light:036]: 'voice_assistant_leds' Setting:
[15:36:21][D][light:047]:   State: ON
[15:36:21][D][light:051]:   Brightness: 66%
[15:36:21][D][light:109]:   Effect: 'Waiting for Command'
[15:36:21][D][power_supply:033]: Enabling power supply.
[15:36:21][D][speaker_media_player:420]: State changed to IDLE
[15:36:21][D][speaker_mixer:319]: Stopping speaker mixer
[15:36:22][D][voice_assistant:641]: Event Type: 11
[15:36:22][D][voice_assistant:802]: Starting STT by VAD
[15:36:22][D][light:036]: 'voice_assistant_leds' Setting:
[15:36:22][D][light:051]:   Brightness: 66%
[15:36:22][D][light:109]:   Effect: 'Listening For Command'
[15:36:23][D][voice_assistant:641]: Event Type: 12
[15:36:23][D][voice_assistant:806]: STT by VAD end
[15:36:23][D][voice_assistant:515]: State changed from STREAMING_MICROPHONE to STOP_MICROPHONE
[15:36:23][D][voice_assistant:522]: Desired state set to AWAITING_RESPONSE
[15:36:23][D][voice_assistant:515]: State changed from STOP_MICROPHONE to STOPPING_MICROPHONE
[15:36:23][D][light:036]: 'voice_assistant_leds' Setting:
[15:36:23][D][light:051]:   Brightness: 66%
[15:36:23][D][light:109]:   Effect: 'Thinking'
[15:36:23][D][voice_assistant:515]: State changed from STOPPING_MICROPHONE to AWAITING_RESPONSE
[15:36:23][D][voice_assistant:515]: State changed from AWAITING_RESPONSE to AWAITING_RESPONSE
[15:36:24][D][power_supply:033]: Enabling power supply.
[15:36:24][D][power_supply:033]: Enabling power supply.
[15:36:25][D][power_supply:033]: Enabling power supply.
[15:36:25][D][power_supply:033]: Enabling power supply.
[15:36:25][D][power_supply:033]: Enabling power supply.
[15:36:26][D][power_supply:033]: Enabling power supply.
[15:36:26][D][power_supply:033]: Enabling power supply.
[15:36:27][D][power_supply:033]: Enabling power supply.
[15:36:27][D][power_supply:033]: Enabling power supply.
[15:36:27][D][power_supply:033]: Enabling power supply.
[15:36:27][D][voice_assistant:641]: Event Type: 4
[15:36:27][D][voice_assistant:669]: Speech recognised as: " Please count from 1 to 10."
[15:36:27][D][voice_assistant:641]: Event Type: 5
[15:36:27][D][voice_assistant:674]: Intent started
[15:36:27][D][voice_assistant:641]: Event Type: 6
[15:36:27][D][voice_assistant:641]: Event Type: 7
[15:36:27][D][voice_assistant:697]: Response: "Processing your request, please wait..."
[15:36:27][D][light:036]: 'voice_assistant_leds' Setting:
[15:36:27][D][light:051]:   Brightness: 66%
[15:36:27][D][light:109]:   Effect: 'Replying'
[15:36:27][D][voice_assistant:641]: Event Type: 8
[15:36:27][D][voice_assistant:717]: Response URL: "http://10.10.1.11:8888/play/d7cd77a08886cd9aa810ddaf058ee881.flac"
[15:36:27][D][voice_assistant:515]: State changed from AWAITING_RESPONSE to STREAMING_RESPONSE
[15:36:27][D][voice_assistant:522]: Desired state set to STREAMING_RESPONSE
[15:36:27][D][media_player:073]: 'Home Assistant Voice Streaming' - Setting
[15:36:27][D][media_player:080]:   Media URL: http://10.10.1.11:8888/play/d7cd77a08886cd9aa810ddaf058ee881.flac
[15:36:27][D][media_player:086]:  Announcement: yes
[15:36:27][D][speaker_media_player:420]: State changed to ANNOUNCING
[15:36:27][D][voice_assistant:641]: Event Type: 2
[15:36:27][D][voice_assistant:731]: Assist Pipeline ended
[15:36:27][D][ring_buffer:034][ann_read]: Created ring buffer with size 1000000
[15:36:27][D][speaker_media_player.pipeline:114]: Reading FLAC file type
[15:36:32][D][voice_assistant:515]: State changed from STREAMING_RESPONSE to IDLE
[15:36:32][D][voice_assistant:522]: Desired state set to IDLE
[15:36:32][D][light:036]: 'voice_assistant_leds' Setting:
[15:36:32][D][light:047]:   State: OFF
[15:36:32][D][light:109]:   Effect: 'None'
[15:36:32][D][speaker_media_player.pipeline:124]: Decoded audio has 2 channels, 24000 Hz sample rate, and 16 bits per sample
[15:36:32][D][ring_buffer:034][sample]: Created ring buffer with size 9600
[15:36:32][D][ring_buffer:034]: Created ring buffer with size 19200
[15:36:32][D][resampler_speaker:059]: Starting resampler task
[15:36:32][D][resampler_speaker:080]: Started resampler task
[15:36:32][D][speaker_mixer:306]: Starting speaker mixer
[15:36:32][D][speaker_mixer:314]: Started speaker mixer
[15:36:35][D][speaker_media_player:420]: State changed to IDLE
[15:36:35][D][speaker_mixer:319]: Stopping speaker mixer
[15:36:35][D][resampler_speaker:085]: Stopping resampler task
[15:36:35][D][resampler_speaker:090]: Stopped resampler task
[15:36:42][D][power_supply:048]: Disabling power supply.
[15:36:44][D][micro_wake_word:355]: Detected 'Okay Nabu' with sliding average probability is 0.89 and max probability is 0.96
[15:36:44][D][media_player:073]: 'Home Assistant Voice Streaming' - Setting
[15:36:44][D][media_player:077]:   Command: STOP
[15:36:44][D][media_player:086]:  Announcement: yes
[15:36:44][D][ring_buffer:034][ann_read]: Created ring buffer with size 1000000
[15:36:44][D][speaker_media_player:420]: State changed to ANNOUNCING
[15:36:44][D][speaker_media_player.pipeline:114]: Reading FLAC file type
[15:36:44][D][speaker_media_player.pipeline:124]: Decoded audio has 1 channels, 48000 Hz sample rate, and 16 bits per sample
[15:36:44][D][ring_buffer:034]: Created ring buffer with size 9600
[15:36:44][D][speaker_mixer:306]: Starting speaker mixer
[15:36:44][D][speaker_mixer:314]: Started speaker mixer
[15:36:44][D][voice_assistant:515]: State changed from IDLE to START_MICROPHONE
[15:36:44][D][voice_assistant:522]: Desired state set to START_PIPELINE
[15:36:44][D][voice_assistant:225]: Starting Microphone
[15:36:44][D][voice_assistant:515]: State changed from START_MICROPHONE to STARTING_MICROPHONE
[15:36:44][D][voice_assistant:515]: State changed from STARTING_MICROPHONE to START_PIPELINE
[15:36:44][D][voice_assistant:280]: Requesting start...
[15:36:44][D][voice_assistant:515]: State changed from START_PIPELINE to STARTING_PIPELINE
[15:36:44][D][voice_assistant:537]: Client started, streaming microphone
[15:36:44][D][voice_assistant:515]: State changed from STARTING_PIPELINE to STREAMING_MICROPHONE
[15:36:44][D][voice_assistant:522]: Desired state set to STREAMING_MICROPHONE
[15:36:44][D][voice_assistant:641]: Event Type: 1
[15:36:44][D][voice_assistant:644]: Assist Pipeline running
[15:36:44][D][voice_assistant:641]: Event Type: 3
[15:36:44][D][voice_assistant:655]: STT started
[15:36:45][D][light:036]: 'voice_assistant_leds' Setting:
[15:36:45][D][light:047]:   State: ON
[15:36:45][D][light:051]:   Brightness: 66%
[15:36:45][D][light:109]:   Effect: 'Waiting for Command'
[15:36:45][D][power_supply:033]: Enabling power supply.
[15:36:45][D][speaker_media_player:420]: State changed to IDLE
[15:36:45][D][speaker_mixer:319]: Stopping speaker mixer
[15:36:46][D][voice_assistant:641]: Event Type: 11
[15:36:46][D][voice_assistant:802]: Starting STT by VAD
[15:36:46][D][light:036]: 'voice_assistant_leds' Setting:
[15:36:46][D][light:051]:   Brightness: 66%
[15:36:46][D][light:109]:   Effect: 'Listening For Command'
[15:36:47][D][voice_assistant:641]: Event Type: 12
[15:36:47][D][voice_assistant:806]: STT by VAD end
[15:36:47][D][voice_assistant:515]: State changed from STREAMING_MICROPHONE to STOP_MICROPHONE
[15:36:47][D][voice_assistant:522]: Desired state set to AWAITING_RESPONSE
[15:36:47][D][voice_assistant:515]: State changed from STOP_MICROPHONE to STOPPING_MICROPHONE
[15:36:47][D][light:036]: 'voice_assistant_leds' Setting:
[15:36:47][D][light:051]:   Brightness: 66%
[15:36:47][D][light:109]:   Effect: 'Thinking'
[15:36:47][D][voice_assistant:515]: State changed from STOPPING_MICROPHONE to AWAITING_RESPONSE
[15:36:47][D][voice_assistant:515]: State changed from AWAITING_RESPONSE to AWAITING_RESPONSE
[15:36:48][D][power_supply:033]: Enabling power supply.
[15:36:48][D][power_supply:033]: Enabling power supply.
[15:36:48][D][power_supply:033]: Enabling power supply.
[15:36:49][D][power_supply:033]: Enabling power supply.
[15:36:49][D][power_supply:033]: Enabling power supply.
[15:36:50][D][power_supply:033]: Enabling power supply.
[15:36:50][D][power_supply:033]: Enabling power supply.
[15:36:50][D][power_supply:033]: Enabling power supply.
[15:36:51][D][power_supply:033]: Enabling power supply.
[15:36:51][D][voice_assistant:641]: Event Type: 4
[15:36:51][D][voice_assistant:669]: Speech recognised as: " Please count from one to ten."
[15:36:51][D][voice_assistant:641]: Event Type: 5
[15:36:51][D][voice_assistant:674]: Intent started
[15:36:51][D][voice_assistant:641]: Event Type: 6
[15:36:51][D][voice_assistant:641]: Event Type: 7
[15:36:51][D][voice_assistant:697]: Response: "Processing your request, please wait..."
[15:36:51][D][light:036]: 'voice_assistant_leds' Setting:
[15:36:51][D][light:051]:   Brightness: 66%
[15:36:51][D][light:109]:   Effect: 'Replying'
[15:36:51][D][voice_assistant:641]: Event Type: 8
[15:36:51][D][voice_assistant:717]: Response URL: "http://10.10.1.11:8888/play/d7cd77a08886cd9aa810ddaf058ee881.flac"
[15:36:51][D][voice_assistant:515]: State changed from AWAITING_RESPONSE to STREAMING_RESPONSE
[15:36:51][D][voice_assistant:522]: Desired state set to STREAMING_RESPONSE
[15:36:51][D][media_player:073]: 'Home Assistant Voice Streaming' - Setting
[15:36:51][D][media_player:080]:   Media URL: http://10.10.1.11:8888/play/d7cd77a08886cd9aa810ddaf058ee881.flac
[15:36:51][D][media_player:086]:  Announcement: yes
[15:36:51][D][power_supply:033]: Enabling power supply.
[15:36:51][D][speaker_media_player:420]: State changed to ANNOUNCING
[15:36:51][D][voice_assistant:641]: Event Type: 2
[15:36:51][D][voice_assistant:731]: Assist Pipeline ended
[15:36:51][D][ring_buffer:034][ann_read]: Created ring buffer with size 1000000
[15:36:51][D][speaker_media_player.pipeline:114]: Reading FLAC file type
[15:36:56][E][speaker_media_player:334]: The announcement pipeline's file reader encountered an error.    <<<<< ERROR <<<<<<<
[15:36:56][D][speaker_media_player:420]: State changed to IDLE
[15:36:56][D][voice_assistant:515]: State changed from STREAMING_RESPONSE to IDLE
[15:36:56][D][voice_assistant:522]: Desired state set to IDLE
[15:36:56][D][light:036]: 'voice_assistant_leds' Setting:
[15:36:56][D][light:047]:   State: OFF
[15:36:56][D][light:109]:   Effect: 'None'
[15:37:07][D][power_supply:048]: Disabling power supply.

TTMG side:

INFO:     Started server process [883793]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://0.0.0.0:8888 (Press CTRL+C to quit)
INFO 15:36:27: GOT USER MESSAGE:  Please count from 1 to 10.
INFO 15:36:27: PLAY
INFO:     10.10.1.25:56185 - "GET /play/d7cd77a08886cd9aa810ddaf058ee881.flac HTTP/1.1" 200 OK
INFO 15:36:28: CALLING LLM
INFO 15:36:29: HTTP Request: POST https://api.openai.com/v1/chat/completions "HTTP/1.1 200 OK"
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: Getting LLM response...
INFO 15:36:29: TTS OPENAI: 1, 2, 3, 4, 5, 6, 7, 8, 9, 10.
INFO 15:36:31: HTTP Request: POST https://api.openai.com/v1/audio/speech "HTTP/1.1 200 OK"
INFO 15:36:51: GOT USER MESSAGE:  Please count from one to ten.
INFO 15:36:51: PLAY
INFO:     10.10.1.25:56186 - "GET /play/d7cd77a08886cd9aa810ddaf058ee881.flac HTTP/1.1" 200 OK
INFO 15:36:51: CALLING LLM
INFO 15:36:54: HTTP Request: POST https://api.openai.com/v1/chat/completions "HTTP/1.1 200 OK"
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:54: Getting LLM response...
INFO 15:36:55: Getting LLM response...
INFO 15:36:55: Getting LLM response...
INFO 15:36:55: Getting LLM response...
INFO 15:36:55: Getting LLM response...
INFO 15:36:55: Getting LLM response...
INFO 15:36:55: Getting LLM response...
INFO 15:36:55: TTS OPENAI: One, two, three, four, five, six, seven, eight, nine, ten.
INFO 15:36:56: HTTP Request: POST https://api.openai.com/v1/audio/speech "HTTP/1.1 200 OK"

[eslavnov]

Heya, thanks for the detailed logs! Would you mind pulling the latest version, re-running the generate_esphome_config.py with an mp3 audio format, and trying the resulting configuration on your HAVPE device? This will skip the encoding to flac and stream the response in mp3. If it works fine then probably it's a bug in my shitty flac encoder, if not - I'll investigate more.

[RobMeades]

Have tried that now and I think it is probably more reliable but the problem is still there.

I've done the following:

• Pulled the latest ttmg onto my ttmg server machine (Ubuntu, on the same LAN as Home Assistant, both with a wired Ethernet connection), re-run ./setup.sh with configuration.json as follows:

  {
    "main":{
      "openai_api_key": "blah",
      "llm_model": "gpt-4o-mini",
      "llm_system_prompt": "You are an expert storyteller. Always respond in English, regardless of the language. Your responses will be announced via a TTS system, so avoid emojis, non-spoken text and abbreviations. Respond as if you are speaking naturally in a casual conversation. Add realistic pauses, filler words like 'um,' 'uh,' 'like,' 'you know,' or 'I mean,' and occasional repetitions or restarts to mimic human speech patterns. These should appear in almost every sentence to create a truly conversational flow.",
      "max_completion_tokens": 400,
      "temperature": 1.0,
      "top_p": 1.0,
      "tts_engine": "openai",
      "host": "0.0.0.0",
      "port": 8888
    }
  }
  

• Pulled the latest ttmg into Home Assistant (restarting Home Assistant afterwards).

• Deleted and re-created the ttmg integration in Home Assistant, pointing it at my ttmg server machine again, settings otherwise default.

• Regenerated the patch code for my HAVPE with python generate_esphome_config.py.

• Copied the new patch files into the ESPHome Device Builder add-on docker container (directory /home/d7cd77a08886cd9aa810ddaf058ee881).

• Cleaned the files of my HAVPE in the ESPHome Device Builder add-on.

• Pasted the following YAML into ESPHome Device Builder for my HAVPE:

  substitutions:
    name: home-assistant-voice-streaming
    friendly_name: Home Assistant Voice Streaming
  
  packages:
    Nabu Casa.Home Assistant Voice PE: github://esphome/home-assistant-voice-pe/home-assistant-voice.yaml
  
  esphome:
    name: ${name}
    name_add_mac_suffix: false
    friendly_name: ${friendly_name}
  api:
    encryption:
      key: "blah"
  
  ota:
    - platform: esphome
      password: "blah"
  
  wifi:
    ssid: !secret wifi_ssid
    password: !secret wifi_password
  
  external_components:
    - source:
        type: local
        path: /home/d7cd77a08886cd9aa810ddaf058ee881
  
  media_player:
    - platform: speaker
      id: !extend external_media_player
      announcement_pipeline:
        speaker: announcement_resampling_speaker
        format: MP3
  

• Built and downloaded this to my HAVPE via OTA (the HAVPE is only 4 metres away from my Wifi access point).

• Left the TTMG Voice Assistant settings as they were, i.e.:

  

• Started ttmg on the TTMG server machine with ./start.sh:

  INFO:     Started server process [994448]
  INFO:     Waiting for application startup.
  INFO:     Application startup complete.
  INFO:     Uvicorn running on http://0.0.0.0:8888 (Press CTRL+C to quit)
  

With that done, in order to be repeatable, I gave the prompt "OK Nabu: please count from one to ten" a few times; this worked fine the first three times and showed the same error as above, on the fourth occasion, i.e.:

[11:09:46][D][speaker_media_player.pipeline:114]: Reading MP3 file type
...5 seconds pass...
[11:09:51][E][speaker_media_player:334]: The announcement pipeline's file reader encountered an error.

Find attached logs from the HAVPE and ttmg server covering all four attempts. Is there anything else I might try, any other information I might gather?

havpe_log.txt
ttmg_server_log.txt

[eslavnov]

Wow, man, thank you so much for such a detailed report - this is amazing! Really appreciate it ❤❤❤
I'll try to look into this during the weekend.