HTTP 500 in `/api/users/me`

[oliverrahner]

Description

Situation:

• freshly set up papermerge, using docker compose (see docker-compose.yml below)
• after logging in, I only get a message stating "Error"
• the request to /api/users/me fails with an HTTP 500

The JWT for the request to /api/users/me is this:

{
  "sub": "oliver",
  "user_id": "506c4976c6fb4262ae9d0647a88e658e",
  "exp": 1705514430
}

In the logs I see:

papermerge-web-1  | Exception in ASGI application
papermerge-web-1  | Traceback (most recent call last):
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/uvicorn/protocols/http/h11_impl.py", line 408, in run_asgi
papermerge-web-1  |     result = await app(  # type: ignore[func-returns-value]
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 84, in __call__
papermerge-web-1  |     return await self.app(scope, receive, send)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/fastapi/applications.py", line 289, in __call__
papermerge-web-1  |     await super().__call__(scope, receive, send)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/starlette/applications.py", line 122, in __call__
papermerge-web-1  |     await self.middleware_stack(scope, receive, send)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/starlette/middleware/errors.py", line 184, in __call__
papermerge-web-1  |     raise exc
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/starlette/middleware/errors.py", line 162, in __call__
papermerge-web-1  |     await self.app(scope, receive, _send)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/starlette/middleware/cors.py", line 83, in __call__
papermerge-web-1  |     await self.app(scope, receive, send)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/starlette/middleware/exceptions.py", line 79, in __call__
papermerge-web-1  |     raise exc
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/starlette/middleware/exceptions.py", line 68, in __call__
papermerge-web-1  |     await self.app(scope, receive, sender)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/fastapi/middleware/asyncexitstack.py", line 20, in __call__
papermerge-web-1  |     raise e
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/fastapi/middleware/asyncexitstack.py", line 17, in __call__
papermerge-web-1  |     await self.app(scope, receive, send)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/starlette/routing.py", line 718, in __call__
papermerge-web-1  |     await route.handle(scope, receive, send)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/starlette/routing.py", line 276, in handle
papermerge-web-1  |     await self.app(scope, receive, send)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/starlette/routing.py", line 66, in app
papermerge-web-1  |     response = await func(request)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/fastapi/routing.py", line 263, in app
papermerge-web-1  |     solved_result = await solve_dependencies(
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/fastapi/dependencies/utils.py", line 586, in solve_dependencies
papermerge-web-1  |     solved = await run_in_threadpool(call, **sub_values)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/starlette/concurrency.py", line 41, in run_in_threadpool
papermerge-web-1  |     return await anyio.to_thread.run_sync(func, *args)
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/anyio/to_thread.py", line 56, in run_sync
papermerge-web-1  |     return await get_async_backend().run_sync_in_worker_thread(
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/anyio/_backends/_asyncio.py", line 2134, in run_sync_in_worker_thread
papermerge-web-1  |     return await future
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/anyio/_backends/_asyncio.py", line 851, in run
papermerge-web-1  |     result = context.run(func, *args)
papermerge-web-1  |   File "/core_app/papermerge/core/auth/__init__.py", line 43, in get_current_user
papermerge-web-1  |     user = db.get_user(engine, user_id)
papermerge-web-1  |   File "/core_app/papermerge/core/db/users.py", line 35, in get_user
papermerge-web-1  |     db_user = session.scalars(stmt, params).one()
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/sqlalchemy/engine/result.py", line 1824, in one
papermerge-web-1  |     return self._only_one_row(
papermerge-web-1  |   File "/core_app/.venv/lib/python3.10/site-packages/sqlalchemy/engine/result.py", line 757, in _only_one_row
papermerge-web-1  |     raise exc.NoResultFound(
papermerge-web-1  | sqlalchemy.exc.NoResultFound: No row was found when one was required

The actual database query is this:

papermerge-web-1  | DEBUG 2024-01-18 08:48:28,361 base SELECT core_user.id, core_user.username, core_user.email, core_user.password, core_user.first_name, core_user.last_name, core_user.is_superuser, core_user.is_staff, core_user.is_active, core_user.home_folder_id, core_user.inbox_folder_id, core_user.created_at, core_user.date_joined, core_user.updated_at
papermerge-web-1  | FROM core_user
papermerge-web-1  | WHERE core_user.username = %s
papermerge-web-1  | DEBUG 2024-01-18 08:48:28,361 base [generated in 0.00021s] ('506c4976c6fb4262ae9d0647a88e658e',)

So seemingly, somewhere username and user id get mixed up, because the query tries to find a user that has his id as name.
When I change the username to the user's id, I can log in, and other issues appear then but maybe that's something for a follow up.

Info:
docker-compose.yml:

version: "3.9"

x-backend: &common
  image: papermerge/papermerge:3.0.1
  environment:
      PAPERMERGE__SECURITY__SECRET_KEY: "6542097834589734"
      PAPERMERGE__AUTH__USERNAME: oliver
      PAPERMERGE__AUTH__PASSWORD: "C9!*SzG4oL&"
      PAPERMERGE__DATABASE__URL: mysql://papermate:CGhmdZEbHLo(Qe-N@host.docker.internal:3306/papermate
      PAPERMERGE__REDIS__URL: redis://redis:6379/0
      PAPERMERGE__SEARCH__URL: solr://solr:8983/pmg-index
      PAPERMERGE__MAIN__LOGGING_CFG: /core_app/logging.yml
  volumes:
    - media_root:/core_app/media
    - ./logging.yml:/core_app/logging.yml
  extra_hosts:
    - "host.docker.internal:host-gateway"
  depends_on:
    - redis
    - solr

services:
  web:
    <<: *common
    ports:
     - "11000:80"
  worker:
    <<: *common
    command: worker
  redis:
    image: redis:6
  solr:
    image: solr:9.3
#    ports:
#     - "8983:8983"
    volumes:
      - solr_data:/var/solr
    command:
      - solr-precreate
      - pmg-index
volumes:
  solr_data:
  media_root:

[schischo]

same here, but with sqlite3

[oliverrahner]

Found the next level of the issue:
user.id is not a UUID, but a 16-byte (32-char) hex string.
That's why is_valid_uuid returns false on this value, leading to a search for username instead of user ID.

[oliverrahner]

The problem is this line:
https://github.com/papermerge/auth-server/blob/0f19caf2c67da2142556b04cd2456bd3af66f250/auth_server/crud.py#L84

So it only relates to user accounts that are created via the auth-server, the creation from inside core seems to be fine, because it does not convert the UUIDs to a pure .hex() representation.

[ciur]

@oliverrahner thank you for awesome report!

Issue seems to happen only with mysql/mariadb/sqlite, but not with postgres.

I will fix auth_server.crud.create_user function to insert UUIDs similarely to the one from the papermerge.core.db.users.create_user.

[oliverrahner]

Sqlalchemy seems to map UUID field types to char columns for mysql (with a fixed 32 char size!), which makes the format very explicit, leading to the issue with these differences…
The fixed size also means that you wouldn’t be able to save the UUID including the dashes, making the fix more complex 😏

[ciur]

@oliverrahner @schischo

I've published 3.0.2 which should fix current issue (uuid/mysql/sqlite thingy).
Also in documentation I've updated docker-compose examples to include healthcheck key - which ensures that webapp/workers will start only after database process (not just db container) is up and running.

[oliverrahner]

@ciur I can confirm this fixed my issue!