I had originally posted the question below the announcement of the 2.5.10 version. Since no response came I thought I’d move my post here for cosmetic reasons at least.
In the meantime I have found a workaround for my problem: Downgrade to 2.5.9 again (see the end of the post).
Now here’s the problem description, maybe this really is a bug.
I’m afraid Rhasspy stopped working for me after upgrading master and satellites to 2.5.10. Before that there was a working 2.5.9 installed. Other than using the docker commands to pull the new image, remove the old container and create/start the new one from the fresh image I did not do anything.
When addressing a satellite verbally the wake word is still recognized, it gives me the usual beep. But after speaking a command nothing seems to be happening anymore, no further beeps either.
For debugging I’m using the webpage of a satellite to submit a command in text form already, meaning the recognize button along with “handle”.
Without looking at the messages themselfes this seems to trigger an infinite loop filling up both logs file until I restart the satellite.
Here’s an excerpt from the master log file; I tried to isolate the repeating part. I see it seems to run into some kind of timeout, but I’m having a hard time figuring out the actual cause.
[DEBUG:2021-04-24 14:03:37,559] rhasspyserver_hermes: -> NluQuery(input='wie ist die uhrzeit', site_id='satellite01', id='730accf8-9781-4275-b0e0-ee35fd394380', intent_filter=None, session_id='730accf8-9781-4275-b0e0-ee35fd394380', wakeword_id=None, lang=None, custom_data=None, asr_confidence=None, custom_entities=None)
[DEBUG:2021-04-24 14:03:37,559] rhasspyserver_hermes: Publishing 279 bytes(s) to hermes/nlu/query
[DEBUG:2021-04-24 14:03:37,580] rhasspyserver_hermes: -> NluQuery(input='wie ist die uhrzeit', site_id='satellite01', id='532dd6e4-d54b-4d94-b103-463299c7c67b', intent_filter=None, session_id='532dd6e4-d54b-4d94-b103-463299c7c67b', wakeword_id=None, lang=None, custom_data=None, asr_confidence=None, custom_entities=None)
[DEBUG:2021-04-24 14:03:37,580] rhasspyserver_hermes: Publishing 279 bytes(s) to hermes/nlu/query
[ERROR:2021-04-24 14:03:37,735] rhasspyserver_hermes:
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 1869, in dispatch_request
return await handler(**request_.view_args)
File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__main__.py", line 1445, in api_text_to_intent
site_id=site_id,
File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__main__.py", line 2699, in text_to_intent_dict
text, intent_filter=intent_filter, site_id=site_id
File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__init__.py", line 523, in recognize_intent
handle_intent(), messages, message_types
File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__init__.py", line 994, in publish_wait
result_awaitable, timeout=timeout_seconds
File "/usr/lib/python3.7/asyncio/tasks.py", line 423, in wait_for
raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
[DEBUG:2021-04-24 14:03:37,760] rhasspyserver_hermes: -> NluQuery(input='wie ist die uhrzeit', site_id='satellite01', id='7271db3a-715e-4322-b561-70a5a9bf1679', intent_filter=None, session_id='7271db3a-715e-4322-b561-70a5a9bf1679', wakeword_id=None, lang=None, custom_data=None, asr_confidence=None, custom_entities=None)
[DEBUG:2021-04-24 14:03:37,760] rhasspyserver_hermes: Publishing 279 bytes(s) to hermes/nlu/query
[ERROR:2021-04-24 14:03:37,763] rhasspyserver_hermes:
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 1869, in dispatch_request
return await handler(**request_.view_args)
File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__main__.py", line 1445, in api_text_to_intent
site_id=site_id,
File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__main__.py", line 2699, in text_to_intent_dict
text, intent_filter=intent_filter, site_id=site_id
File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__init__.py", line 523, in recognize_intent
handle_intent(), messages, message_types
File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__init__.py", line 994, in publish_wait
result_awaitable, timeout=timeout_seconds
File "/usr/lib/python3.7/asyncio/tasks.py", line 423, in wait_for
raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
[DEBUG:2021-04-24 14:03:37,804] rhasspyserver_hermes: -> NluQuery(input='wie ist die uhrzeit', site_id='satellite01', id='b9c0f9b7-e031-4cb1-8878-810b0f2c170b', intent_filter=None, session_id='b9c0f9b7-e031-4cb1-8878-810b0f2c170b', wakeword_id=None, lang=None, custom_data=None, asr_confidence=None, custom_entities=None)
[DEBUG:2021-04-24 14:03:37,804] rhasspyserver_hermes: Publishing 279 bytes(s) to hermes/nlu/query
And this is from the satellite:
[DEBUG:2021-04-24 14:04:37,666] rhasspyremote_http_hermes: http://rhasspy-master:12101/api/text-to-intent params={'siteId': 'satellite01'}
[ERROR:2021-04-24 14:04:37,812] rhasspyremote_http_hermes: handle_query
Traceback (most recent call last):
File "/usr/lib/rhasspy/rhasspy-remote-http-hermes/rhasspyremote_http_hermes/__init__.py", line 293, in handle_query
response.raise_for_status()
File "/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/aiohttp/client_reqrep.py", line 1005, in raise_for_status
headers=self.headers,
aiohttp.client_exceptions.ClientResponseError: 500, message='', url=URL('http://rhasspy-master:12101/api/text-to-intent?siteId=satellite01')
[DEBUG:2021-04-24 14:04:37,815] rhasspyremote_http_hermes: -> NluError(error="ClientResponseError(RequestInfo(url=URL('http://rhasspy-master:12101/api/text-to-intent?siteId=satellite01'), method='POST', headers=<CIMultiDictProxy('Host': 'rhasspy-master:12101', 'Accept': '*/*', 'Accept-Encoding': 'gzip, deflate', 'User-Agent': 'Python/3.7 aiohttp/3.7.4', 'Content-Length': '19', 'Content-Type': 'text/plain; charset=utf-8')>, real_url=URL('http://rhasspy-master:12101/api/text-to-intent?siteId=satellite01')), (), status=500, headers=<CIMultiDictProxy('Content-Type': 'text/html; charset=utf-8', 'Content-Length': '14', 'Date': 'Sat, 24 Apr 2021 12:04:37 GMT', 'Server': 'hypercorn-h11')>)", site_id='satellite01', context="NluQuery(input='wie ist die uhrzeit', site_id='satellite01', id='a5a412e9-c969-43f2-80bd-be98e0bc72ba', intent_filter=None, session_id='a5a412e9-c969-43f2-80bd-be98e0bc72ba', wakeword_id=None, lang=None, custom_data=None, asr_confidence=None, custom_entities=None)", session_id='a5a412e9-c969-43f2-80bd-be98e0bc72ba')
[DEBUG:2021-04-24 14:04:37,816] rhasspyremote_http_hermes: Publishing 982 bytes(s) to hermes/error/nlu
[DEBUG:2021-04-24 14:04:37,834] rhasspyremote_http_hermes: <- NluQuery(input='wie ist die uhrzeit', site_id='satellite01', id='f6365a05-276e-4822-a15d-900bac658da4', intent_filter=None, session_id='f6365a05-276e-4822-a15d-900bac658da4', wakeword_id=None, lang=None, custom_data=None, asr_confidence=None, custom_entities=None)
[DEBUG:2021-04-24 14:04:37,834] rhasspyremote_http_hermes: http://rhasspy-master:12101/api/text-to-intent params={'siteId': 'satellite01'}
[ERROR:2021-04-24 14:04:37,846] rhasspyremote_http_hermes: handle_query
Traceback (most recent call last):
File "/usr/lib/rhasspy/rhasspy-remote-http-hermes/rhasspyremote_http_hermes/__init__.py", line 293, in handle_query
response.raise_for_status()
File "/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/aiohttp/client_reqrep.py", line 1005, in raise_for_status
headers=self.headers,
aiohttp.client_exceptions.ClientResponseError: 500, message='', url=URL('http://rhasspy-master:12101/api/text-to-intent?siteId=satellite01')
[DEBUG:2021-04-24 14:04:37,849] rhasspyremote_http_hermes: -> NluError(error="ClientResponseError(RequestInfo(url=URL('http://rhasspy-master:12101/api/text-to-intent?siteId=satellite01'), method='POST', headers=<CIMultiDictProxy('Host': 'rhasspy-master:12101', 'Accept': '*/*', 'Accept-Encoding': 'gzip, deflate', 'User-Agent': 'Python/3.7 aiohttp/3.7.4', 'Content-Length': '19', 'Content-Type': 'text/plain; charset=utf-8')>, real_url=URL('http://rhasspy-master:12101/api/text-to-intent?siteId=satellite01')), (), status=500, headers=<CIMultiDictProxy('Content-Type': 'text/html; charset=utf-8', 'Content-Length': '14', 'Date': 'Sat, 24 Apr 2021 12:04:37 GMT', 'Server': 'hypercorn-h11')>)", site_id='satellite01', context="NluQuery(input='wie ist die uhrzeit', site_id='satellite01', id='edaddd31-1ea1-4f1f-ba12-3825c4bbcb3c', intent_filter=None, session_id='edaddd31-1ea1-4f1f-ba12-3825c4bbcb3c', wakeword_id=None, lang=None, custom_data=None, asr_confidence=None, custom_entities=None)", session_id='edaddd31-1ea1-4f1f-ba12-3825c4bbcb3c')
[DEBUG:2021-04-24 14:04:37,850] rhasspyremote_http_hermes: Publishing 982 bytes(s) to hermes/error/nlu
[DEBUG:2021-04-24 14:04:37,871] rhasspyremote_http_hermes: <- NluQuery(input='wie ist die uhrzeit', site_id='satellite01', id='dec882ec-4d9b-4a70-9380-3252d0e0e6dc', intent_filter=None, session_id='dec882ec-4d9b-4a70-9380-3252d0e0e6dc', wakeword_id=None, lang=None, custom_data=None, asr_confidence=None, custom_entities=None)
[DEBUG:2021-04-24 14:04:37,872] rhasspyremote_http_hermes: http://rhasspy-master:12101/api/text-to-intent params={'siteId': 'satellite01'}
I’ve uploaded the complete logs here:
https://server47.de/download/temp/docker_master.txt
https://server47.de/download/temp/docker_satellite.txt
I’ve clicked the “recognize” button at 13:47:00 pretty much on the spot.
I’m not sure if I didn’t read a part of the release notes or if I’ve discovered some sort of bug.
Any help would be much appreciated!
Workaround: Downgrade to 2.5.9
docker stop containerName && docker rm containerName
docker rmi -f $(docker images -a -q)
docker pull rhasspy/rhasspy:2.5.9
docker run -d -p 12101:12101 --name rhasspy --restart unless-stopped -v "$HOME/.config/rhasspy/profiles:/profiles" -v "/etc/localtime:/etc/localtime:ro" rhasspy/rhasspy:2.5.9 --user-profiles /profiles --profile de
After downgrading the master and satellites again everything worked as it did before.