Hi everyone,
I’m happily running Rhasspy and after a few hours (sometimes minutes) I’m getting a weird error out of the blue which looks like this (check extended output logs at the bottom of the post in Appendix A
):
overrun!!! (at least 463171.246 ms long)
arecord: xrun:1642: xrun: prepare error: Input/output error
(the number of ms varies from a few minutes to several hours!)
this error seems to originate around https://github.com/rhasspy/rhasspy-wake-porcupine-hermes/blob/91af83bcd5fcbe34e3971fb802dcf0baf6cd7416/rhasspywake_porcupine_hermes/__init__.py#L266
A bit of info:
version: rhasspy 2.5.11 (the hash of rhasspy wake seems to be 91af83b
according to github)
platform: raspberry pi zero w
uname -r
output: Linux rpi0 5.15.84+ #1613 Thu Jan 5 11:58:09 GMT 2023 armv6l GNU/Linux
how it’s running: I’m running it in a docker container using host’s pulse through alsa as per https://github.com/rhasspy/rhasspy/tree/master/examples/docker-compose-pulseaudio
audio I/O: I’m using a ReSpeaker 6-Mic Circular Array kit for Raspberry Pi
and a forked version of the official drivers from here https://github.com/HinTak/seeed-voicecard/tree/v5.16
(nothing major, they’re just applying some patches for forward compatibility)
alsa/pulse host config: default configs provided by the seeed repo here https://github.com/respeaker/seeed-voicecard/tree/8cce4e8ffa77e1e2b89812e5e2ccf6cfbc1086cf/pulseaudio
(just commented out minor stuff like suspend-on-idle and rescue-stream as they were respectively not necessary and deprecated)
startup mode: satellite communicating with base over MQTT (snapcast runs as a client as well for what it matters)
By the same means I’m running a snapcast container that, when the overrun occurs in rhasspy, coincidentally throws the following repeatedly
ALSA lib pulse.c:242:(pulse_connect) PulseAudio: Unable to connect: Connection refused
2023-01-27 13-22-06.726 [Error] (Alsa) Exception in initAlsa: Can't open default, error: Connection refused
ALSA lib pulse.c:242:(pulse_connect) PulseAudio: Unable to connect: Connection refused
2023-01-27 13-22-06.849 [Error] (Alsa) Exception in initAlsa: Can't open default, error: Connection refused
If I restart both containers (rhasspy and snapcast client) everything works again. (no need to restart pulse or the raspberry itself).
By the symptoms it looks like wakeword is listening and filling up the audio buffer without really reading it until it explodes, but I might be wrong and maybe someone more familiar with the code might help.
The error seems to originate from alsa-utils arecord itself https://github.com/alsa-project/alsa-utils/blob/v1.1.8/aplay/aplay.c#L1609
.
That’s the right version as arecord --version
returns
arecord: version 1.1.8 by Jaroslav Kysela <perex@perex.cz>
also yes, aplay/arecord are in the same source-file under aplay.c
$ ls -lah $(which arecord)
lrwxrwxrwx 1 root root 5 Mar 18 2021 /usr/bin/arecord -> aplay
Allow me to re-iterate that when everything works, everything works amazingly (both rhasspy and snapcast); Just after a few hours (sometime minutes) this happens out of the blue and it breaks both of the containers.
It’s totally possible that I’m asking too much to the raspi and I should try to move to the zero 2 w, but before getting there I’d like to confirm my suspects.
Thank you everyone
edit: I tested it on a raspberry pi zero 2 w with a 64bit OS and got the same issue. Also I tried running the rhasspy container without running the snapcast one and it triggered the issue after about 30s after it started listening for the wake word
Appendix A
extended log output:
[DEBUG:2023-01-26 15:50:37,245] rhasspyspeakers_cli_hermes: ['aplay', '-q', '-t', 'wav', '-D', 'pulse']
[DEBUG:2023-01-26 15:50:38,102] rhasspyserver_hermes: <- NluIntent(input='turn off Kitchen', intent=Intent(intent_name='HassTurnOff', confidence_score=1.0), site_id='satellite1', id=None, slots=[Slot(entity='hass/entities', value={'kind': 'Unknown', 'value': 'Kitchen'}, slot_name='name', raw_value='kitchen', confidence=1.0, range=SlotRange(start=9, end=16, raw_start=9, raw_end=16))], session_id='satellite1-porcupine_raspberry-pi-db4ac4e2-5e1e-440b-acb4-4b8a3918cf64', custom_data='porcupine_raspberry-pi', asr_tokens=[[AsrToken(value='turn', confidence=1.0, range_start=0, range_end=4, time=None), AsrToken(value='off', confidence=1.0, range_start=5, range_end=8, time=None), AsrToken(value='Kitchen', confidence=1.0, range_start=9, range_end=16, time=None)]], asr_confidence=0.999133561, raw_input='turn off kitchen', wakeword_id='porcupine_raspberry-pi', lang=None)
[DEBUG:2023-01-26 15:50:38,142] rhasspyserver_hermes: Sent 660 char(s) to websocket
[DEBUG:2023-01-26 15:50:39,334] rhasspyspeakers_cli_hermes: -> AudioPlayFinished(id='3e94564d-94f8-40f7-b5fc-cab203babc43', session_id='3e94564d-94f8-40f7-b5fc-cab203babc43')
[DEBUG:2023-01-26 15:50:39,351] rhasspyspeakers_cli_hermes: Publishing 99 bytes(s) to hermes/audioServer/satellite1/playFinished
[DEBUG:2023-01-26 15:51:03,431] rhasspymicrophone_cli_hermes: <- AsrStopListening(site_id='satellite1', session_id='satellite1-porcupine_raspberry-pi-db4ac4e2-5e1e-440b-acb4-4b8a3918cf64')
[DEBUG:2023-01-26 15:51:03,446] rhasspywake_porcupine_hermes: <- HotwordToggleOn(site_id='satellite1', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2023-01-26 15:51:03,465] rhasspymicrophone_cli_hermes: Enable UDP output
[DEBUG:2023-01-26 15:51:03,479] rhasspywake_porcupine_hermes: Enabled
[DEBUG:2023-01-26 15:51:03,512] rhasspywake_porcupine_hermes: Receiving audio satellite1
overrun!!! (at least 463171.246 ms long)
arecord: xrun:1642: xrun: prepare error: Input/output error
[DEBUG:2023-01-26 21:15:53,342] rhasspyspeakers_cli_hermes: ['aplay', '-q', '-t', 'wav', '-D', 'pulse']
[DEBUG:2023-01-26 21:15:54,173] rhasspyserver_hermes: <- NluIntent(input='turn off Living Room TV', intent=Intent(intent_name='HassTurnOff', confidence_score=1.0), site_id='satellite1', id=None, slots=[Slot(entity='hass/entities', value={'kind': 'Unknown', 'value': 'Living Room TV'}, slot_name='name', raw_value='living room tv', confidence=1.0, range=SlotRange(start=9, end=23, raw_start=9, raw_end=23))], session_id='satellite1-porcupine_raspberry-pi-7fcc5b72-2d7b-4975-855c-40a1bb715592', custom_data='porcupine_raspberry-pi', asr_tokens=[[AsrToken(value='turn', confidence=1.0, range_start=0, range_end=4, time=None), AsrToken(value='off', confidence=1.0, range_start=5, range_end=8, time=None), AsrToken(value='Living', confidence=1.0, range_start=9, range_end=15, time=None), AsrToken(value='Room', confidence=1.0, range_start=16, range_end=20, time=None), AsrToken(value='TV', confidence=1.0, range_start=21, range_end=23, time=None)]], asr_confidence=0.9881059, raw_input='turn off living room tv', wakeword_id='porcupine_raspberry-pi', lang=None)
[DEBUG:2023-01-26 21:15:56,063] rhasspyspeakers_cli_hermes: -> AudioPlayFinished(id='b3c195ca-6fea-46c6-bf81-3cccf3ef02ec', session_id='b3c195ca-6fea-46c6-bf81-3cccf3ef02ec')
[DEBUG:2023-01-26 21:15:56,095] rhasspyspeakers_cli_hermes: Publishing 99 bytes(s) to hermes/audioServer/satellite1/playFinished
[DEBUG:2023-01-26 21:16:18,770] rhasspywake_porcupine_hermes: <- HotwordToggleOn(site_id='satellite1', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2023-01-26 21:16:18,780] rhasspywake_porcupine_hermes: Enabled
[DEBUG:2023-01-26 21:16:18,764] rhasspymicrophone_cli_hermes: <- AsrStopListening(site_id='satellite1', session_id='satellite1-porcupine_raspberry-pi-7fcc5b72-2d7b-4975-855c-40a1bb715592')
[DEBUG:2023-01-26 21:16:18,794] rhasspymicrophone_cli_hermes: Enable UDP output
[DEBUG:2023-01-26 21:16:18,788] rhasspywake_porcupine_hermes: Receiving audio satellite1
overrun!!! (at least 22620297.518 ms long)
arecord: xrun:1642: xrun: prepare error: Input/output error