search

rhasspy / rhasspy-server-hermes

Web server interface to Rhasspy with Hermes back-end
MIT License
4 stars 18 forks source link

Logspam with swagger UI websocket failures running the rhasspy docker image #19

Closed jrouly closed 3 years ago

jrouly commented 4 years ago

Environment: running rhasspy:latest (be3bbfdf4e23) on docker.

Symptom: whenever the browser is open to the Rhasspy web server, websocket connections are made to:

/api/events/log
/api/events/audiosummary

These websocket requests appear to fail with Unexpected response code 500, but that's beside the point. Nothing appears the matter in the browser for the most part.

The thing that's really problematic is the logspam in the container output, which makes it very difficult to track what's going on:

quart.exceptions.NotFound: NotFound(404)
[ERROR:2020-10-20 20:55:41,136] rhasspyserver_hermes: NotFound(404)
Traceback (most recent call last):
  File "/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/quart/static.py", line 129, in safe_join
    full_path = file_path_to_path(directory, *paths).resolve(strict=True)
  File "/usr/lib/python3.7/pathlib.py", line 1151, in resolve
    s = self._flavour.resolve(self, strict=strict)
  File "/usr/lib/python3.7/pathlib.py", line 355, in resolve
    return _resolve(base, str(path)) or sep
  File "/usr/lib/python3.7/pathlib.py", line 339, in _resolve
    target = accessor.readlink(newpath)
  File "/usr/lib/python3.7/pathlib.py", line 437, in readlink
    return os.readlink(path)
FileNotFoundError: [Errno 2] No such file or directory: '/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/swagger_ui/static/events'

During handling of the above exception, another exception occurred:

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/.venv/lib/python3.7/site-packages/quart/static.py", line 88, in send_static_file
    return await send_from_directory(self.static_folder, filename)
  File "/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/quart/static.py", line 161, in send_from_directory
    file_path = safe_join(directory, file_name)
  File "/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/quart/static.py", line 131, in safe_join
    raise NotFound()

I was able to narrow down the websocket requests as the problem by attaching to the running container and creating the directories that the FileNotFoundError was complaining about (static directories inside the virtual environment), which resulted in these newer errors:

FileNotFoundError: [Errno 2] No such file or directory: '/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/swagger_ui/static/events/audiosummary'
FileNotFoundError: [Errno 2] No such file or directory: '/usr/lib/rhasspy/.venv/lib/python3.7/site-packages/swagger_ui/static/events/log'

and then creating those subsequent directories resolved the second level of exceptions. But I'm still seeing a ton of NotFound(404) error messages in container output, presumably for each of those websocket calls.

jrouly commented 4 years ago

After attaching to the live container and poking through the code there some, it looks like it might be out of date with latest master in this repo. Is the publication schedule for rhasspy/rhasspy:latest out of sync with merges?

synesthesiam commented 4 years ago

Hi @jrouly, thanks for looking into this. I've had a lot of weird cases with Quart's websockets, and this is the first time I'm seeing them triggering an exception because the server is interpreting them as a request for a static file. I don't see this at all when I run outside a container on my machine.

Is the publication schedule for rhasspy/rhasspy:latest out of sync with merges?

Nothing automated, unfortunately. Myself and other Rhasspy developers have tried getting the build process onto Github, but it's pretty ugly and long. It's a docker buildx process that simultaneously builds images for amd64, arm/v7, arm64, and arm/v6 with a lot of Python dependencies and pre-compiled binaries. And now I'm trying to shove PyTorch in there :smile:

synesthesiam commented 4 years ago

P.S. You can fight some of the log spam by passing some additional command-line arguments:

$ docker run ... rhasspy/rhasspy ... -- --log-level info

Note the -- separator that ensures everything after is passed directly to rhasspy-server-hermes. Additionally, you can edit the supervisord.conf file in your profile and adjust logging there; it's re-generated each time you save your profile or restart, so pass --nogenerate-conf alongside --profile, etc. to avoid overwriting your changes.