Warming up rhasspy

Help
1

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

2

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?
3

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

4

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…

5

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

6

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…

7

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.

8

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:

9

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
10

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:

11

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…

12

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: