Warming up rhasspy

HI all!
Does anyone have issues after a long time of inactivity?
There are no errors in the log it just works really slow…
For example in the morning when I say “Snowboy” I have to wait ~20-30 sec before I hear beep_hi. After that it works as usual with no delays.
I do not do anything to start rhasspy working - just wait

Is it possible to warm up rhasspy somehow? I still can’t fix this issue by myself :grimacing:

Some investigations: I think the issue is in aplay command. Because I see “hotword is detected” immediately, but with no sound
Also when I press Play Recording button in the interface I have some delays for the first time

I don’t think this is coming from Rhasspy directly but just to be sure…

  • What kind of device do you use to run Rhasspy?
  • Do you use an external MQTT broker?
  • Do you use WIFI or Ethernet cable?

Hi @fastjack

  • I’m using rpi 3b+
  • It was external MQTT, but I’ve swithed a week ago to the internal - no success =(
  • It’s ethernet

One more investigation… When I press [play recording] after the delay, I hear beep_hi wav recorded. This means rhasspy started recording before aplay command is finished
Normally it doesn’t happen

I was thinking that the MQTT connection might get closed after a long period of inactivity but with the internal broker and/or an Ethernet connection that should not be the case.

Can you provide the logs when this « delay » happens. That would help pinpoint where this delay occurs… Maybe also your Rhasspy config…

There is nothing strange in the logs:

[DEBUG:2020-10-08 06:13:17,433] rhasspyserver_hermes: Sent 276 char(s) to websocket
[DEBUG:2020-10-08 06:13:14,462] rhasspyserver_hermes: <- NluIntentNotRecognized(input='', site_id='default', id=None, custom_data=None, session_id='default-snowboy-2e0cd4c4-1cbc-49be-ab50-13695dde800e')
[DEBUG:2020-10-08 06:12:52,320] rhasspyserver_hermes: <- HotwordDetected(model_id='snowboy', model_version='', model_type='personal', current_sensitivity=0.5, site_id='default', session_id=None, send_audio_captured=None, lang=None)

06:12:52,320 is the time when I said my hotword… But it was without beep_hi sound
I heard it later and rhasspy recorded it as a command and tried to parse.

Below is my config:

{
    "command": {
        "webrtcvad": {
            "silence_sec": 0.3,
            "vad_mode": 3
        }
    },
    "dialogue": {
        "system": "rhasspy"
    },
    "handle": {
        "system": "hass"
    },
    "home_assistant": {
        "access_token": "XXXXXXXXXXXXXXXXXXXXX",
        "handle_type": "event",
        "url": "http://1.1.1.1:8123/"
    },
    "intent": {
        "fsticuffs": {
            "fuzzy": false
        },
        "fuzzywuzzy": {
            "min_confidence": "0.7"
        },
        "system": "fsticuffs"
    },
    "microphone": {
        "system": "arecord"
    },
    "mqtt": {
        "enabled": "",
        "host": "1.1.1.1"
    },
    "sounds": {
        "aplay": {
            "device": "hw:CARD=Headphones,DEV=0"
        },
        "system": "aplay"
    },
    "speech_to_text": {
        "system": "kaldi"
    },
    "text_to_speech": {
        "system": "picotts"
    },
    "wake": {
        "snowboy": {
            "audio_gain": "1.5",
            "sensitivity": "0.5"
        },
        "system": "snowboy"
    }
}

One more investigation:
This morning before talking to rhasspy I ran aplay command on my host system and there were no delays. So maybe it’s docker issue… next morning I will try to run aplay from rhasspy container

So this is docker issue…
when I run
docker container exec rhasspy aplay -D plughw:1,0 /usr/lib/rhasspy/etc/wav/beep_hi.wav
sometimes I have to wait. But if I run the command directly from my host there is no delay

Does anyone know how to fix it? Looks like docker takes resources from rhasspy container after some time…

Hello All,
I have the same issue with this log on 2 satellites (Raspberry PI ZERO WH and Raspberry PI 3B+) / rhasspy 2.5.6 / wake word HERMES MQTT on the master (raven) :

[ERROR:2020-10-10 17:15:17,044] rhasspyserver_hermes: NotFound(404)
Traceback (most recent call last):
File “/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/quart/app.py”, line 1821, in full_dispatch_request
result = await self.dispatch_request(request_context)
File “/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/quart/app.py”, line 1863, in dispatch_request
raise request_.routing_exception
quart.exceptions.NotFound: NotFound(404)
[ERROR:2020-10-10 17:15:16,864] rhasspyserver_hermes: NotFound(404)
Traceback (most recent call last):
File “/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/quart/app.py”, line 1821, in full_dispatch_request
result = await self.dispatch_request(request_context)
File “/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/quart/app.py”, line 1863, in dispatch_request
raise request_.routing_exception
quart.exceptions.NotFound: NotFound(404)

To unblock this issue on my 2 rhasspys, I can write for example a sigle command in the UI.

Sometimes I see the result of a command earlier than I hear beep_lo confirmation sound.
For example, rhasspy sends command to HA, HA turns on my light and only after 1-2 secs I hear sound…
Maybe it’s reading speed. Or something like cache? So weird :thinking:

Hi all. It’s me again =)
I have cheked logs right from docker container… Below is the line showing starting of playing beep_hi sound

[DEBUG:2020-11-23 13:41:42,602] rhasspydialogue_hermes: -> AudioPlayBytes(83948 byte(s)) to hermes/audioServer/default/playBytes/5b2cec16-f76e-4bc8-beaa-382a646d3081

But it has been finished after ~5 secs. Even after rhasspyasr_kaldi_hermes: -> AsrRecordingFinished

[DEBUG:2020-11-23 13:41:48,150] rhasspyspeakers_cli_hermes: -> AudioPlayFinished(id='5b2cec16-f76e-4bc8-beaa-382a646d3081', session_id='5b2cec16-f76e-4bc8-beaa-382a646d3081')

Below is the full log showing all details. @fastjack, @synesthesiam do you have any ideas? I still can’t solve this issue :roll_eyes:

[DEBUG:2020-11-23 13:41:41,948] rhasspywake_snowboy_hermes: Wake word detected: snowboy (site_id=default)
[DEBUG:2020-11-23 13:41:42,643] rhasspyasr_kaldi_hermes: <- AsrToggleOff(site_id='default', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:42,644] rhasspyasr_kaldi_hermes: Disabled (AsrToggleReason.PLAY_AUDIO)
[DEBUG:2020-11-23 13:41:42,374] rhasspydialogue_hermes: <- HotwordDetected(model_id='snowboy', model_version='', model_type='personal', current_sensitivity=0.5, site_id='default', session_id=None, send_audio_captured=None, lang=None)
[DEBUG:2020-11-23 13:41:42,504] rhasspydialogue_hermes: Playing WAV /usr/lib/rhasspy/etc/wav/beep_hi.wav
[DEBUG:2020-11-23 13:41:42,597] rhasspydialogue_hermes: -> HotwordToggleOff(site_id='default', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:42,598] rhasspydialogue_hermes: Publishing 44 bytes(s) to hermes/hotword/toggleOff
[DEBUG:2020-11-23 13:41:42,601] rhasspydialogue_hermes: -> AsrToggleOff(site_id='default', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:42,601] rhasspydialogue_hermes: Publishing 44 bytes(s) to hermes/asr/toggleOff
[DEBUG:2020-11-23 13:41:42,602] rhasspydialogue_hermes: -> AudioPlayBytes(83948 byte(s)) to hermes/audioServer/default/playBytes/5b2cec16-f76e-4bc8-beaa-382a646d3081
[DEBUG:2020-11-23 13:41:42,605] rhasspydialogue_hermes: Waiting for playFinished (id=5b2cec16-f76e-4bc8-beaa-382a646d3081, timeout=1.2012925170068027)
[DEBUG:2020-11-23 13:41:42,262] rhasspywake_snowboy_hermes: -> HotwordDetected(model_id='snowboy', model_version='', model_type='personal', current_sensitivity=0.5, site_id='default', session_id=None, send_audio_captured=None, lang=None)
[DEBUG:2020-11-23 13:41:42,262] rhasspywake_snowboy_hermes: Publishing 175 bytes(s) to hermes/hotword/snowboy/detected
[DEBUG:2020-11-23 13:41:42,643] rhasspywake_snowboy_hermes: <- HotwordToggleOff(site_id='default', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:42,644] rhasspywake_snowboy_hermes: Disabled
[DEBUG:2020-11-23 13:41:42,611] rhasspyspeakers_cli_hermes: <- AudioPlayBytes(83948 byte(s))
[DEBUG:2020-11-23 13:41:42,612] rhasspyspeakers_cli_hermes: ['aplay', '-q', '-t', 'wav', '-D', 'hw:CARD=Headphones,DEV=0']
[WARNING:2020-11-23 13:41:43,809] rhasspydialogue_hermes: Did not receive sayFinished before timeout
[DEBUG:2020-11-23 13:41:43,811] rhasspydialogue_hermes: -> HotwordToggleOn(site_id='default', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:43,812] rhasspydialogue_hermes: Publishing 44 bytes(s) to hermes/hotword/toggleOn
[DEBUG:2020-11-23 13:41:43,815] rhasspydialogue_hermes: -> AsrToggleOn(site_id='default', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:43,815] rhasspydialogue_hermes: Publishing 44 bytes(s) to hermes/asr/toggleOn
[DEBUG:2020-11-23 13:41:43,817] rhasspywake_snowboy_hermes: <- HotwordToggleOn(site_id='default', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:43,817] rhasspywake_snowboy_hermes: Enabled
[WARNING:2020-11-23 13:41:43,819] rhasspydialogue_hermes: No session for id default-snowboy-1bc4b514-d5b9-487e-8999-0f104a58f0c8
[DEBUG:2020-11-23 13:41:43,819] rhasspydialogue_hermes: Handling queued session
[DEBUG:2020-11-23 13:41:43,820] rhasspydialogue_hermes: Session aborted: default-snowboy-1bc4b514-d5b9-487e-8999-0f104a58f0c8
[WARNING:2020-11-23 13:41:43,820] rhasspydialogue_hermes: No session for id default-snowboy-1bc4b514-d5b9-487e-8999-0f104a58f0c8
[DEBUG:2020-11-23 13:41:43,824] rhasspyasr_kaldi_hermes: <- AsrToggleOn(site_id='default', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:43,822] rhasspydialogue_hermes: -> HotwordToggleOn(site_id='default', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-11-23 13:41:43,823] rhasspydialogue_hermes: Publishing 50 bytes(s) to hermes/hotword/toggleOn
[DEBUG:2020-11-23 13:41:43,824] rhasspydialogue_hermes: Starting new session (id=default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66)
[DEBUG:2020-11-23 13:41:43,825] rhasspyasr_kaldi_hermes: Enabled
[DEBUG:2020-11-23 13:41:43,826] rhasspydialogue_hermes: -> DialogueSessionStarted(session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', site_id='default', custom_data='snowboy', lang=None)
[DEBUG:2020-11-23 13:41:43,827] rhasspydialogue_hermes: Publishing 129 bytes(s) to hermes/dialogueManager/sessionStarted
[DEBUG:2020-11-23 13:41:43,841] rhasspyasr_kaldi_hermes: <- AsrStartListening(site_id='default', session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', lang=None, stop_on_silence=True, send_audio_captured=True, wakeword_id='snowboy', intent_filter=None)
[DEBUG:2020-11-23 13:41:43,842] rhasspyasr_kaldi_hermes: Creating new transcriber session default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66
[DEBUG:2020-11-23 13:41:43,843] rhasspyasr_kaldi.transcribe: Using kaldi at /usr/lib/rhasspy/.venv/lib/kaldi
[DEBUG:2020-11-23 13:41:43,830] rhasspydialogue_hermes: -> HotwordToggleOff(site_id='default', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-11-23 13:41:43,832] rhasspydialogue_hermes: Publishing 50 bytes(s) to hermes/hotword/toggleOff
[DEBUG:2020-11-23 13:41:43,833] rhasspydialogue_hermes: Listening for session default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66
[DEBUG:2020-11-23 13:41:43,835] rhasspydialogue_hermes: -> AsrStartListening(site_id='default', session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', lang=None, stop_on_silence=True, send_audio_captured=True, wakeword_id='snowboy', intent_filter=None)
[DEBUG:2020-11-23 13:41:43,835] rhasspydialogue_hermes: Publishing 201 bytes(s) to hermes/asr/startListening
[DEBUG:2020-11-23 13:41:43,831] rhasspywake_snowboy_hermes: <- HotwordToggleOn(site_id='default', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-11-23 13:41:43,831] rhasspywake_snowboy_hermes: Enabled
[DEBUG:2020-11-23 13:41:43,835] rhasspywake_snowboy_hermes: <- HotwordToggleOff(site_id='default', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-11-23 13:41:43,836] rhasspywake_snowboy_hermes: Disabled
[DEBUG:2020-11-23 13:41:43,880] rhasspyasr_kaldi.transcribe: ['/usr/lib/rhasspy/.venv/lib/kaldi/online2-tcp-nnet3-decode-faster', '--port-num=52684', '--config=/profiles/en/kaldi/model/online/conf/online.conf', '--frame-subsampling-factor=3', '--max-active=7000', '--lattice-beam=8.0', '--acoustic-scale=1.0', '--beam=24.0', '/profiles/en/kaldi/model/model/final.mdl', '/profiles/en/kaldi/model/graph/HCLG.fst', '/profiles/en/kaldi/model/graph/words.txt']
[DEBUG:2020-11-23 13:41:43,881] rhasspyasr_kaldi_hermes: Starting listening (session_id=default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66)
[DEBUG:2020-11-23 13:41:43,961] rhasspyasr_kaldi_hermes: Receiving audio
[DEBUG:2020-11-23 13:41:45,264] rhasspyasr_kaldi_hermes: -> AsrRecordingFinished(site_id='default', session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66')
[DEBUG:2020-11-23 13:41:45,264] rhasspyasr_kaldi_hermes: Publishing 90 bytes(s) to rhasspy/asr/recordingFinished
[DEBUG:2020-11-23 13:41:48,150] rhasspyspeakers_cli_hermes: -> AudioPlayFinished(id='5b2cec16-f76e-4bc8-beaa-382a646d3081', session_id='5b2cec16-f76e-4bc8-beaa-382a646d3081')
[DEBUG:2020-11-23 13:41:48,151] rhasspyspeakers_cli_hermes: Publishing 99 bytes(s) to hermes/audioServer/default/playFinished
[DEBUG:2020-11-23 13:41:48,159] rhasspydialogue_hermes: <- AudioPlayFinished(id='5b2cec16-f76e-4bc8-beaa-382a646d3081', session_id='5b2cec16-f76e-4bc8-beaa-382a646d3081')
[DEBUG:2020-11-23 13:41:48,191] rhasspytts_cli_hermes: <- AudioPlayFinished(id='5b2cec16-f76e-4bc8-beaa-382a646d3081', session_id='5b2cec16-f76e-4bc8-beaa-382a646d3081')
[DEBUG:2020-11-23 13:41:48,302] rhasspyasr_kaldi.transcribe: /usr/lib/rhasspy/.venv/lib/kaldi/online2-tcp-nnet3-decode-faster --port-num=52684 --config=/profiles/en/kaldi/model/online/conf/online.conf --frame-subsampling-factor=3 --max-active=7000 --lattice-beam=8.0 --acoustic-scale=1.0 --beam=24.0 /profiles/en/kaldi/model/model/final.mdl /profiles/en/kaldi/model/graph/hclg.fst /profiles/en/kaldi/model/graph/words.txt
[DEBUG:2020-11-23 13:41:49,594] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:computederivedvars():ivector-extractor.cc:183) computing derived variables for ivector extractor
[DEBUG:2020-11-23 13:41:50,395] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:computederivedvars():ivector-extractor.cc:204) done.
[DEBUG:2020-11-23 13:41:51,088] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:removeorphannodes():nnet-nnet.cc:948) removed 1 orphan nodes.
[DEBUG:2020-11-23 13:41:51,088] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:removeorphancomponents():nnet-nnet.cc:847) removing 2 orphan components.
[DEBUG:2020-11-23 13:41:51,089] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:collapse():nnet-utils.cc:1472) added 1 components, removed 2
[DEBUG:2020-11-23 13:41:51,224] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:compilelooped():nnet-compile-looped.cc:345) spent 0.0997529 seconds in looped compilation.
[DEBUG:2020-11-23 13:41:51,322] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:listen():online2-tcp-nnet3-decode-faster.cc:379) tcpserver: listening on port: 52684
[DEBUG:2020-11-23 13:41:51,322] rhasspyasr_kaldi.transcribe: log (online2-tcp-nnet3-decode-faster[5.5]:accept():online2-tcp-nnet3-decode-faster.cc:393) waiting for client...
[DEBUG:2020-11-23 13:41:51,322] rhasspyasr_kaldi.transcribe: Decoder started
[DEBUG:2020-11-23 13:41:51,364] rhasspyasr_kaldi.transcribe: Finished stream. Getting transcription.
[DEBUG:2020-11-23 13:41:52,810] rhasspyasr_kaldi.transcribe: ['kodi service ', 'kodi service off ']
[DEBUG:2020-11-23 13:41:52,812] rhasspyasr_kaldi_hermes: Transcription result: Transcription(text='kodi service off', likelihood=1, transcribe_seconds=1.447506689990405, wav_seconds=1.472, tokens=None)
[DEBUG:2020-11-23 13:41:52,816] rhasspyasr_kaldi_hermes: -> AsrTextCaptured(text='kodi service off', likelihood=1, seconds=1.447506689990405, site_id='default', session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', wakeword_id=None, asr_tokens=None, lang=None)
[DEBUG:2020-11-23 13:41:52,816] rhasspyasr_kaldi_hermes: Publishing 218 bytes(s) to hermes/asr/textCaptured
[DEBUG:2020-11-23 13:41:52,818] rhasspyasr_kaldi_hermes: -> AsrAudioCaptured(43244 byte(s)) to rhasspy/asr/default/default/audioCaptured
[DEBUG:2020-11-23 13:41:52,855] rhasspydialogue_hermes: <- AsrTextCaptured(text='kodi service off', likelihood=1, seconds=1.447506689990405, site_id='default', session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', wakeword_id=None, asr_tokens=None, lang=None)
[DEBUG:2020-11-23 13:41:52,857] rhasspydialogue_hermes: Playing WAV /usr/lib/rhasspy/etc/wav/beep_lo.wav
[DEBUG:2020-11-23 13:41:52,875] rhasspydialogue_hermes: -> HotwordToggleOff(site_id='default', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:52,876] rhasspydialogue_hermes: Publishing 44 bytes(s) to hermes/hotword/toggleOff
[DEBUG:2020-11-23 13:41:52,879] rhasspydialogue_hermes: -> AsrToggleOff(site_id='default', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:52,879] rhasspydialogue_hermes: Publishing 44 bytes(s) to hermes/asr/toggleOff
[DEBUG:2020-11-23 13:41:52,881] rhasspydialogue_hermes: -> AudioPlayBytes(119908 byte(s)) to hermes/audioServer/default/playBytes/fbdd153a-55d0-46ca-af0b-4ba54208a52a
[DEBUG:2020-11-23 13:41:52,883] rhasspydialogue_hermes: Waiting for playFinished (id=fbdd153a-55d0-46ca-af0b-4ba54208a52a, timeout=1.6090022675736961)
[DEBUG:2020-11-23 13:41:52,890] rhasspyspeakers_cli_hermes: <- AudioPlayBytes(119908 byte(s))
[DEBUG:2020-11-23 13:41:52,891] rhasspyspeakers_cli_hermes: ['aplay', '-q', '-t', 'wav', '-D', 'hw:CARD=Headphones,DEV=0']
[DEBUG:2020-11-23 13:41:52,894] rhasspywake_snowboy_hermes: <- HotwordToggleOff(site_id='default', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:52,895] rhasspywake_snowboy_hermes: Disabled
[DEBUG:2020-11-23 13:41:52,946] rhasspyasr_kaldi_hermes: <- AsrToggleOff(site_id='default', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:52,946] rhasspyasr_kaldi_hermes: Disabled (AsrToggleReason.PLAY_AUDIO)
[DEBUG:2020-11-23 13:41:53,778] rhasspyspeakers_cli_hermes: -> AudioPlayFinished(id='fbdd153a-55d0-46ca-af0b-4ba54208a52a', session_id='fbdd153a-55d0-46ca-af0b-4ba54208a52a')
[DEBUG:2020-11-23 13:41:53,792] rhasspyspeakers_cli_hermes: Publishing 99 bytes(s) to hermes/audioServer/default/playFinished
[DEBUG:2020-11-23 13:41:53,804] rhasspydialogue_hermes: <- AudioPlayFinished(id='fbdd153a-55d0-46ca-af0b-4ba54208a52a', session_id='fbdd153a-55d0-46ca-af0b-4ba54208a52a')
[DEBUG:2020-11-23 13:41:53,809] rhasspydialogue_hermes: -> HotwordToggleOn(site_id='default', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:53,809] rhasspytts_cli_hermes: <- AudioPlayFinished(id='fbdd153a-55d0-46ca-af0b-4ba54208a52a', session_id='fbdd153a-55d0-46ca-af0b-4ba54208a52a')
[DEBUG:2020-11-23 13:41:53,810] rhasspydialogue_hermes: Publishing 44 bytes(s) to hermes/hotword/toggleOn
[DEBUG:2020-11-23 13:41:53,815] rhasspydialogue_hermes: -> AsrToggleOn(site_id='default', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:53,815] rhasspydialogue_hermes: Publishing 44 bytes(s) to hermes/asr/toggleOn
[DEBUG:2020-11-23 13:41:53,817] rhasspydialogue_hermes: Received text: kodi service off
[DEBUG:2020-11-23 13:41:53,820] rhasspydialogue_hermes: -> AsrStopListening(site_id='default', session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66')
[DEBUG:2020-11-23 13:41:53,821] rhasspydialogue_hermes: Publishing 90 bytes(s) to hermes/asr/stopListening
[DEBUG:2020-11-23 13:41:53,824] rhasspydialogue_hermes: -> HotwordToggleOn(site_id='default', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-11-23 13:41:53,825] rhasspydialogue_hermes: Publishing 50 bytes(s) to hermes/hotword/toggleOn
[DEBUG:2020-11-23 13:41:53,828] rhasspywake_snowboy_hermes: <- HotwordToggleOn(site_id='default', reason=<HotwordToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:53,831] rhasspydialogue_hermes: -> NluQuery(input='kodi service off', site_id='default', id=None, intent_filter=None, session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', wakeword_id='snowboy', lang=None)
[DEBUG:2020-11-23 13:41:53,832] rhasspydialogue_hermes: Publishing 192 bytes(s) to hermes/nlu/query
[DEBUG:2020-11-23 13:41:53,835] rhasspyasr_kaldi_hermes: <- AsrToggleOn(site_id='default', reason=<AsrToggleReason.PLAY_AUDIO: 'playAudio'>)
[DEBUG:2020-11-23 13:41:53,837] rhasspyasr_kaldi_hermes: Enabled
[DEBUG:2020-11-23 13:41:53,829] rhasspywake_snowboy_hermes: Still disabled: {<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>}
[DEBUG:2020-11-23 13:41:53,841] rhasspywake_snowboy_hermes: <- HotwordToggleOn(site_id='default', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-11-23 13:41:53,842] rhasspywake_snowboy_hermes: Enabled
[DEBUG:2020-11-23 13:41:53,848] rhasspyasr_kaldi_hermes: <- AsrStopListening(site_id='default', session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66')
[DEBUG:2020-11-23 13:41:53,850] rhasspyasr_kaldi_hermes: Stopping listening (session_id=default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66)
[DEBUG:2020-11-23 13:41:53,853] rhasspyasr_kaldi_hermes: Receiving audio
[DEBUG:2020-11-23 13:41:53,872] rhasspynlu_hermes: <- NluQuery(input='kodi service off', site_id='default', id=None, intent_filter=None, session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', wakeword_id='snowboy', lang=None)
[DEBUG:2020-11-23 13:41:53,918] rhasspynlu_hermes: -> NluIntentParsed(input='switch.kodi off', intent=Intent(intent_name='TurnOnOff', confidence_score=1.0), site_id='default', id=None, slots=[Slot(entity='device', value={'kind': 'Unknown', 'value': 'switch.kodi'}, slot_name='device', raw_value='kodi service', confidence=1.0, range=SlotRange(start=0, end=11, raw_start=0, raw_end=12)), Slot(entity='state', value={'kind': 'Unknown', 'value': 'off'}, slot_name='state', raw_value='off', confidence=1.0, range=SlotRange(start=12, end=15, raw_start=13, raw_end=16))], session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66')
[DEBUG:2020-11-23 13:41:53,932] rhasspynlu_hermes: Publishing 603 bytes(s) to hermes/nlu/intentParsed
[DEBUG:2020-11-23 13:41:53,961] rhasspynlu_hermes: -> NluIntent(input='switch.kodi off', intent=Intent(intent_name='TurnOnOff', confidence_score=1.0), site_id='default', id=None, slots=[Slot(entity='device', value={'kind': 'Unknown', 'value': 'switch.kodi'}, slot_name='device', raw_value='kodi service', confidence=1.0, range=SlotRange(start=0, end=11, raw_start=0, raw_end=12)), Slot(entity='state', value={'kind': 'Unknown', 'value': 'off'}, slot_name='state', raw_value='off', confidence=1.0, range=SlotRange(start=12, end=15, raw_start=13, raw_end=16))], session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', custom_data=None, asr_tokens=[[AsrToken(value='switch.kodi', confidence=1.0, range_start=0, range_end=11, time=None), AsrToken(value='off', confidence=1.0, range_start=12, range_end=15, time=None)]], asr_confidence=None, raw_input='kodi service off', wakeword_id='snowboy', lang=None)
[DEBUG:2020-11-23 13:41:53,962] rhasspynlu_hermes: Publishing 911 bytes(s) to hermes/intent/TurnOnOff
[DEBUG:2020-11-23 13:41:54,026] rhasspyhomeassistant_hermes: <- NluIntent(input='switch.kodi off', intent=Intent(intent_name='TurnOnOff', confidence_score=1.0), site_id='default', id=None, slots=[Slot(entity='device', value={'kind': 'Unknown', 'value': 'switch.kodi'}, slot_name='device', raw_value='kodi service', confidence=1.0, range=SlotRange(start=0, end=11, raw_start=0, raw_end=12)), Slot(entity='state', value={'kind': 'Unknown', 'value': 'off'}, slot_name='state', raw_value='off', confidence=1.0, range=SlotRange(start=12, end=15, raw_start=13, raw_end=16))], session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', custom_data=None, asr_tokens=[[AsrToken(value='switch.kodi', confidence=1.0, range_start=0, range_end=11, time=None), AsrToken(value='off', confidence=1.0, range_start=12, range_end=15, time=None)]], asr_confidence=None, raw_input='kodi service off', wakeword_id='snowboy', lang=None)
[DEBUG:2020-11-23 13:41:54,021] rhasspydialogue_hermes: <- NluIntent(input='switch.kodi off', intent=Intent(intent_name='TurnOnOff', confidence_score=1.0), site_id='default', id=None, slots=[Slot(entity='device', value={'kind': 'Unknown', 'value': 'switch.kodi'}, slot_name='device', raw_value='kodi service', confidence=1.0, range=SlotRange(start=0, end=11, raw_start=0, raw_end=12)), Slot(entity='state', value={'kind': 'Unknown', 'value': 'off'}, slot_name='state', raw_value='off', confidence=1.0, range=SlotRange(start=12, end=15, raw_start=13, raw_end=16))], session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', custom_data=None, asr_tokens=[[AsrToken(value='switch.kodi', confidence=1.0, range_start=0, range_end=11, time=None), AsrToken(value='off', confidence=1.0, range_start=12, range_end=15, time=None)]], asr_confidence=None, raw_input='kodi service off', wakeword_id='snowboy', lang=None)
[DEBUG:2020-11-23 13:41:54,029] rhasspydialogue_hermes: Recognized NluIntent(input='switch.kodi off', intent=Intent(intent_name='TurnOnOff', confidence_score=1.0), site_id='default', id=None, slots=[Slot(entity='device', value={'kind': 'Unknown', 'value': 'switch.kodi'}, slot_name='device', raw_value='kodi service', confidence=1.0, range=SlotRange(start=0, end=11, raw_start=0, raw_end=12)), Slot(entity='state', value={'kind': 'Unknown', 'value': 'off'}, slot_name='state', raw_value='off', confidence=1.0, range=SlotRange(start=12, end=15, raw_start=13, raw_end=16))], session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', custom_data=None, asr_tokens=[[AsrToken(value='switch.kodi', confidence=1.0, range_start=0, range_end=11, time=None), AsrToken(value='off', confidence=1.0, range_start=12, range_end=15, time=None)]], asr_confidence=None, raw_input='kodi service off', wakeword_id='snowboy', lang=None)
[DEBUG:2020-11-23 13:41:54,065] rhasspyhomeassistant_hermes: http://XX.XX.XX.XX:8123/api/events/rhasspy_TurnOnOff
[ERROR:2020-11-23 13:42:13,850] rhasspydialogue_hermes: Session timed out for site default: default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66
[DEBUG:2020-11-23 13:42:13,853] rhasspydialogue_hermes: -> AsrStopListening(site_id='default', session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66')
[DEBUG:2020-11-23 13:42:13,854] rhasspydialogue_hermes: Publishing 90 bytes(s) to hermes/asr/stopListening
[DEBUG:2020-11-23 13:42:13,859] rhasspydialogue_hermes: -> DialogueSessionEnded(termination=DialogueSessionTermination(reason=<DialogueSessionTerminationReason.TIMEOUT: 'timeout'>), session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66', site_id='default', custom_data='snowboy')
[DEBUG:2020-11-23 13:42:13,860] rhasspydialogue_hermes: Publishing 153 bytes(s) to hermes/dialogueManager/sessionEnded
[DEBUG:2020-11-23 13:42:13,863] rhasspydialogue_hermes: -> HotwordToggleOn(site_id='default', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-11-23 13:42:13,864] rhasspydialogue_hermes: Publishing 50 bytes(s) to hermes/hotword/toggleOn
[DEBUG:2020-11-23 13:42:13,894] rhasspywake_snowboy_hermes: <- HotwordToggleOn(site_id='default', reason=<HotwordToggleReason.DIALOGUE_SESSION: 'dialogueSession'>)
[DEBUG:2020-11-23 13:42:13,894] rhasspyasr_kaldi_hermes: <- AsrStopListening(site_id='default', session_id='default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66')
[DEBUG:2020-11-23 13:42:13,895] rhasspyasr_kaldi_hermes: Stopping listening (session_id=default-snowboy-b39e3665-c879-4ed5-bf4c-d2b62a4cbe66)
[DEBUG:2020-11-23 13:42:13,895] rhasspywake_snowboy_hermes: Enabled

Hi @frkos, my guess is there is some delay related to the sound hardware/software. Is this using a built-in speaker or a USB sound card? Also, do you have anything special using the audio hardware outside of Rhasspy?

Some things to try might be:

  • Using a different device from aplay -L (with or without conversions)
  • Trying a different audio play command (play is in the Docker container by default, but you could install others)
  • Messing around with the asound.conf inside the container (some examples here)

As a truly hacky workaround, you could probably send a WAV file with just silence every now and then to keep it warmed up :stuck_out_tongue:

sox -n would just play permanent silence which is ok for pulseaudio but for Alsa you would prob have to set up a dmix pcm for output otherwise one way or another you likely to have a collision of device in use.

pcm.dmixer { type dmix ipc_key 1024 slave { pcm "hw:1,0" period_time 0 period_size 1024 buffer_size 4096 rate 44100 } bindings { 0 0 1 1 } }
Plenty of easy dmix examples you can google.

I am not sure as presuming they are recording on the same device so if it was a power option and sleep there would be no recording for a beep to reply to…

There was a problem with the Pi Zero that over time the webserver caused a lot of load there are threads lost in the forum somewhere but can not remember the exact details.

Anyone checked if pulseaudio -k works as pulseaudio runs in the user space as To unblock this issue on my 2 rhasspys, I can write for example a single command in the UI. does sound like something is waking up but is it the card? Guess it will as just being a cmd it will, so not much of a test.
I always get confused if you guys are running just Alsa or Pluseaudio sinks/sources.

Or maybe disable suspend?
sudo systemctl mask sleep.target suspend.target hibernate.target hybrid-sleep.target

Remember to run in docker and also the host.

Or append usbcore.autosuspend=-1 in /boot/cmdline.txt if it is usb…

Thank you all for replies.
The issue is caused by performance. Assigning more resources to Rhasspy container caused similar issues with other ones. So I will have to optimize/upgrade my host :thinking: