No audio response / media_player audio playback

VivantSenior commented 6 months ago

Flavor

MicroWakeWord

Checklist

[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..
[X] I am able to consult debug logging for my ESPHome instance.

Describe the issue

After update done in PR #39 I noticed that no audio response and no media_player output works. Looking in the logs following error is common for both issues: esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x7780. Based on the search looks like it is related to the certificates (esp-idf/8375) or shortage of RAM (HTTPS connection fail). Yes, I have already tried #13.

Sometimes I get issues like esp-tls: couldn't get hostname for :ha.domain.com: getaddrinfo() returns 202, addrinfo=0x0. Would it e possible esphome to use mDNS or private IP of my HA?

Related issues: #34, #13, esphome/2179 (feature request ignored for over a year).

Reproduction steps

Invoke wake word and say something to the mic.

Debug logs

Audio response:
[15:21:58][D][voice_assistant:439]: State changed from STOPPING_MICROPHONE to AWAITING_RESPONSE
[15:22:05][D][voice_assistant:563]: Event Type: 4
[15:22:05][D][voice_assistant:591]: Speech recognised as: " Cześć, cześć, cześć, cześć, cześć!"
[15:22:05][D][voice_assistant:563]: Event Type: 5
[15:22:05][D][voice_assistant:596]: Intent started
[15:22:06][D][voice_assistant:563]: Event Type: 6
[15:22:06][D][voice_assistant:563]: Event Type: 7
[15:22:06][D][voice_assistant:619]: Response: "Wybacz, niestety nie mogę tego zrozumieć"
[15:22:06][D][voice_assistant:563]: Event Type: 8
[15:22:06][D][voice_assistant:639]: Response URL: "https://ha.domain.com/api/tts_proxy/x_tts.piper.mp3"
[15:22:06][D][voice_assistant:439]: State changed from AWAITING_RESPONSE to STREAMING_RESPONSE
[15:22:06][D][voice_assistant:445]: Desired state set to STREAMING_RESPONSE
[15:22:06][D][media_player:059]: 'None' - Setting
[15:22:06][D][media_player:066]:   Media URL: https://ha.domain.com/api/tts_proxy/x_tts.piper.mp3
[15:22:06][D][adf_media_player:030]: Got control call in state 1
[15:22:06][D][esp_adf_pipeline:050]: Starting request, current state STOPPED
[15:22:06][D][esp_adf_pipeline:302]: State changed from STOPPED to PREPARING
[15:22:06][I][adf_media_player:135]: got new pipeline state: 1
[15:22:06][D][adf_i2s_out:127]: Set final i2s settings: 16000
[15:22:06][D][esp_audio_processors:079]: New settings: SRC: rate: 16000, ch: 2 DST: rate: 16000, ch: 2 
[15:22:06][D][light:036]: 'top_led' Setting:
[15:22:06][D][light:059]:   Red: 20%, Green: 100%, Blue: 0%
[15:22:06][D][light:109]:   Effect: 'speaking'
[15:22:06][D][voice_assistant:563]: Event Type: 2
[15:22:06][D][voice_assistant:653]: Assist Pipeline ended
[15:22:06][D][esp-idf:000]: I (256993) AUDIO_ELEMENT: [http] AEL_MSG_CMD_RESUME,state:1

[15:22:06][D][esp-idf:000]: I (256996) AUDIO_ELEMENT: [decoder] AEL_MSG_CMD_RESUME,state:1

[15:22:06][D][esp_audio_sources:097]: Streamer status: 2
[15:22:06][D][esp_audio_sources:098]: decoder status: 2
[15:22:06][D][esp-idf:000]: E (257039) esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x7780

[15:22:06][D][esp-idf:000]: E (257043) esp-tls: Failed to open new connection

[15:22:06][D][esp-idf:000]: E (257047) TRANSPORT_BASE: Failed to open a new connection

[15:22:06][D][esp-idf:000]: E (257055) HTTP_CLIENT: Connection failed, sock < 0

[15:22:06][D][esp-idf:000]: E (257058) HTTP_STREAM: Failed to open http stream

[15:22:06][D][esp-idf:000]: E (257063) AUDIO_ELEMENT: [http] AEL_STATUS_ERROR_OPEN,28674

[15:22:06][D][esp-idf:000]: W (257067) AUDIO_ELEMENT: [http] audio_element_on_cmd_error,7

[15:22:06][D][esp-idf:000]: W (257072) AUDIO_ELEMENT: IN-[decoder] AEL_IO_ABORT

[15:22:06][D][esp-idf:000]: E (257075) MP3_DECODER: failed to read audio data (line 117)

[15:22:06][D][esp-idf:000]: W (257079) AUDIO_ELEMENT: [decoder] AEL_IO_ABORT, -3

[15:22:06][D][esp-idf:000]: I (257083) MP3_DECODER: Closed

[15:22:16][I][esp_adf_pipeline:185]: Pipeline preparation timeout!
[15:22:16][D][esp-idf:000]: W (266967) AUDIO_PIPELINE: Without stop, st:1

[15:22:16][D][esp_adf_pipeline:302]: State changed from PREPARING to STOPPING
[15:22:16][I][adf_media_player:135]: got new pipeline state: 4
[15:22:16][D][esp_adf_pipeline:302]: State changed from STOPPING to STOPPED
[15:22:16][I][adf_media_player:135]: got new pipeline state: 5

Media player:
[15:10:00][D][media_player:059]: 'None' - Setting
[15:10:00][D][media_player:066]:   Media URL: https://ha.domain.com/media/local/file.mp3?authSig=xxx
[15:10:00][D][adf_media_player:030]: Got control call in state 1
[15:10:00][D][esp_adf_pipeline:050]: Starting request, current state STOPPED
[15:10:00][D][esp_adf_pipeline:302]: State changed from STOPPED to PREPARING
[15:10:00][I][adf_media_player:135]: got new pipeline state: 1
[15:10:00][D][adf_i2s_out:127]: Set final i2s settings: 16000
[15:10:00][D][esp_audio_processors:079]: New settings: SRC: rate: 16000, ch: 2 DST: rate: 16000, ch: 2 
[15:10:00][D][esp-idf:000]: I (2336207) AUDIO_ELEMENT: [http] AEL_MSG_CMD_RESUME,state:1

[15:10:00][D][esp-idf:000]: I (2336210) AUDIO_ELEMENT: [decoder] AEL_MSG_CMD_RESUME,state:1

[15:10:00][D][esp_audio_sources:097]: Streamer status: 2
[15:10:00][D][esp_audio_sources:098]: decoder status: 2
[15:10:00][D][esp-idf:000]: E (2336255) esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x7780

[15:10:00][D][esp-idf:000]: E (2336257) esp-tls: Failed to open new connection

[15:10:00][D][esp-idf:000]: E (2336260) TRANSPORT_BASE: Failed to open a new connection

[15:10:00][D][esp-idf:000]: E (2336266) HTTP_CLIENT: Connection failed, sock < 0

[15:10:00][D][esp-idf:000]: E (2336268) HTTP_STREAM: Failed to open http stream

[15:10:00][D][esp-idf:000]: E (2336271) AUDIO_ELEMENT: [http] AEL_STATUS_ERROR_OPEN,28674

[15:10:00][D][esp-idf:000]: W (2336274) AUDIO_ELEMENT: [http] audio_element_on_cmd_error,7

[15:10:00][D][esp-idf:000]: W (2336277) AUDIO_ELEMENT: IN-[decoder] AEL_IO_ABORT

[15:10:00][D][esp-idf:000]: E (2336281) MP3_DECODER: failed to read audio data (line 117)

[15:10:00][D][esp-idf:000]: W (2336284) AUDIO_ELEMENT: [decoder] AEL_IO_ABORT, -3

[15:10:00][D][esp-idf:000]: I (2336287) MP3_DECODER: Closed

[15:10:10][I][esp_adf_pipeline:185]: Pipeline preparation timeout!
[15:10:10][D][esp-idf:000]: W (2346201) AUDIO_PIPELINE: Without stop, st:1

[15:10:10][D][esp_adf_pipeline:302]: State changed from PREPARING to STOPPING
[15:10:10][I][adf_media_player:135]: got new pipeline state: 4
[15:10:10][D][esp_adf_pipeline:302]: State changed from STOPPING to STOPPED
[15:10:10][I][adf_media_player:135]: got new pipeline state: 5

After few tries of use of the media_player to play some mp3:
ERROR Fatal error: protocol.data_received() call failed.
protocol: <aioesphomeapi._frame_helper.noise.APINoiseFrameHelper object at 0x7f95f74040>
transport: <_SelectorSocketTransport fd=6 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib/python3.11/asyncio/selector_events.py", line 1009, in _read_ready__data_received
    self._protocol.data_received(data)
  File "aioesphomeapi/_frame_helper/noise.py", line 136, in aioesphomeapi._frame_helper.noise.APINoiseFrameHelper.data_received
  File "aioesphomeapi/_frame_helper/noise.py", line 163, in aioesphomeapi._frame_helper.noise.APINoiseFrameHelper.data_received
  File "aioesphomeapi/_frame_helper/noise.py", line 319, in aioesphomeapi._frame_helper.noise.APINoiseFrameHelper._handle_frame
  File "/usr/local/lib/python3.11/dist-packages/noise/state.py", line 74, in decrypt_with_ad
    plaintext = self.cipher.decrypt(self.k, self.n, ad, ciphertext)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/dist-packages/noise/backends/default/ciphers.py", line 13, in decrypt
    return self.cipher.decrypt(nonce=self.format_nonce(n), data=ciphertext, associated_data=ad)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "src/chacha20poly1305_reuseable/__init__.py", line 127, in chacha20poly1305_reuseable.ChaCha20Poly1305Reusable.decrypt
  File "src/chacha20poly1305_reuseable/__init__.py", line 147, in chacha20poly1305_reuseable.ChaCha20Poly1305Reusable.decrypt
  File "src/chacha20poly1305_reuseable/__init__.py", line 263, in chacha20poly1305_reuseable._decrypt_with_fixed_nonce_len
  File "src/chacha20poly1305_reuseable/__init__.py", line 273, in chacha20poly1305_reuseable._decrypt_data
cryptography.exceptions.InvalidTag
WARNING office-voice-assistant @ 192.168.0.192: Connection error occurred: office-voice-assistant @ 192.168.0.192: Invalid encryption key: received_name=office-voice-assistant
INFO Processing unexpected disconnect from ESPHome API for office-voice-assistant @ 192.168.0.192
WARNING Disconnected from API
INFO Successfully connected to office-voice-assistant @ 192.168.0.192 in 0.004s
INFO Successful handshake with office-voice-assistant @ 192.168.0.192 in 0.076s

VivantSenior commented 6 months ago

I think it's something strongly related to esp-idf handling https connection because my ESP32-C3 based eBUS Adapter by john30 also returned the "0x7780" error after update to the newest 20240518 firmware:

11:32:57 | Warning | host: errors: protocol
11:35:38 | Error | esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x7780
11:35:38 | Error | esp_https_server: esp_tls_create_server_session failed, 0x7780
11:35:38 | Error | httpd: httpd_accept_conn: session creation failed
11:35:38 | Warning | httpd: httpd_server: error accepting new connection
11:35:46 | Error | esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x7780
11:35:46 | Error | esp_https_server: esp_tls_create_server_session failed, 0x7780
11:35:46 | Error | httpd: httpd_accept_conn: session creation failed
11:35:46 | Warning | httpd: httpd_server: error accepting new connection

dreimer1986 commented 5 months ago

Why don't you set the internal HA URL to the IP and http? https://github.com/tetele/onju-voice-satellite/issues/48 Had the same issue and now all is fine.

VivantSenior commented 5 months ago

@dreimer1986, could you please point me in the right direction on how to set HA internal IP address to be used by ESPHome media_player component? Checked docs of API Native component and media_player and can't find it there. The only place I can set local HA address is Network tab in HA. But for the reason I have ssl I can't use http and can provide IP. Just can use https://homeassistant.local:8123.

dreimer1986 commented 5 months ago

Network tab is right. The internal url is what I had to fix. As I never needed it before it was incorrectly set to https and non existing cert. I set it to http and all is fine here now. I use a reverse proxy anyways for external access and as such internal unencrypted communication is no problem.

tetele / onju-voice-satellite