LibrePhotos / librephotos

A self-hosted open source photo management service. This is the repository of the backend.
MIT License
6.99k stars 306 forks source link

New docker-compose-gpu installation, backend | Method Not Allowed: /api/scanphotos/ #1336

Closed maxya closed 2 months ago

maxya commented 3 months ago

🛑 Before you create an issue make sure that:

When Submitting please remove every thing above this line

🐛 Bug Report

📝 Description of issue:

New install of librephotos-gpu with docker-compose following documentation does not scan for the photos, says "method not allowed. The .env and docker-compose.yaml were identical from configuration that was working fine on standard cpu-only image, I've decided to try gpu image with fresh data folder.

grep -i 'Method Not Allowed' *
gunicorn_django.log:Method Not Allowed: /api/scanphotos/
gunicorn_django.log:Method Not Allowed: /api/scanphotos/
gunicorn_django.log:Method Not Allowed: /api/fullscanphotos/
gunicorn_django.log:Method Not Allowed: /api/fullscanphotos/
gunicorn_django.log:Method Not Allowed: /api/scanphotos/
gunicorn_django.log:Method Not Allowed: /api/scanphotos/

🔁 How can we reproduce it:

fresh install of the librephotos-gpu , start scan or full scan of library.

Please provide additional information:

wchorski commented 3 months ago

Permissions Issue?

I assumed this was an issue with file permissions.

I got into the proxy's bash

docker exec -it librephotos_proxy bash

listed the directories

root@92afb3f46d7f:/# ls -la 
total 80
drwxr-xr-x   1 root root 4096 Aug  9 19:03 .
drwxr-xr-x   1 root root 4096 Aug  9 19:03 ..
...
drwxrwxr-x   5 1000 1000 4096 Aug  9 17:15 data
...
drwxr-xr-x   3 root root 4096 Aug  9 19:10 protected_media

noticed that /data was set to user 1000 so I ran root@92afb3f46d7f:/# chown -R root:root /data while in the proxy container to change ownership of all files and directories recursively.

Still getting the same backend Method Not Allowed: /api/scanphotos/ error

Backend container first log lines

At the top of the logs upon initial boot of the Backend container

Unauthorized: /api/persons/
Unauthorized: /api/sitesettings
Unauthorized: /api/rqavailable/
Unauthorized: /api/user/3/
Unauthorized: /api/storagestats
Unauthorized: /api/stats/
Unauthorized: /api/nextcloud/listdir/
Unauthorized: /api/auth/token/refresh/
Unauthorized: /api/auth/token/refresh/
Unauthorized: /api/auth/token/refresh/
Unauthorized: /api/auth/token/refresh/
Unauthorized: /api/auth/token/refresh/
Unauthorized: /api/auth/token/refresh/
Unauthorized: /api/auth/token/refresh/
Unauthorized: /api/auth/token/refresh/
Unauthorized: /api/auth/token/refresh/
Unauthorized: /api/auth/token/refresh/
[2024-08-09 19:13:45 +0000] [266] [INFO] Autorestarting worker after current request.
[2024-08-09 19:13:45 +0000] [266] [INFO] Worker exiting (pid: 266)
[2024-08-09 19:13:46 +0000] [303] [INFO] Booting worker with pid: 303
use SECRET_KEY from file

Maybe a secret key issue

Thought maybe setting the shhhhKey var in the .env file would solve this issue. I copied the contents from secret.key exactly to the env file. The backend container logs confirmed the switch

# before
backend   | use SECRET_KEY from file

# after adding in `.env` file
backend   | use SECRET_KEY from env

still having same problem and moving back to non -gpu image

maxya commented 3 months ago

For me, exactly same configuration (same volume mounts, same yaml config) works just fine by using non-gpu container.
In my understanding, the Unauthorized message is related in context of caller no-authorized to call api endpoint rather than file permissions on a drive.

polaroidkidd commented 3 months ago

yeah, seeing the same issue with the latest gpu container. Maybe something in the proxy?

derneuere commented 3 months ago

This is probably related to authentication. Can you go to the application tab in your browser and remove all the cookies related to LibrePhotos and try again?

wchorski commented 3 months ago

Deleted cookies

I deleted all cookies and logged in. I see a new csrftoken and jwt added image image

I will note that These errors in this issue happen while not even accessing the ui. They appear upon first spin up of the container before I open any UI in the browser

backend gpu container logs

...
librephotos_backend   | 22:31:35 [Q] INFO Enqueued [DjangORM] 16255
librephotos_backend   | 22:31:35 [Q] INFO Process-892f16f82c8d4aa496d9040878b6b0f4 created task sink-kansas-music-zebra from schedule [1]
librephotos_backend   | 22:31:36 [Q] INFO Process-a133011e3b9d497c95c9837297f4cdec processing sink-kansas-music-zebra 'api.services.check_services' [1]
librephotos_backend   | 22:31:36 [Q] ERROR Failed 'api.services.check_services' (sink-kansas-music-zebra) - Function api.services.check_services is not defined : Traceback (most recent call last):
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django_q/worker.py", line 96, in worker
librephotos_backend   |     raise ValueError(f"Function {task['func']} is not defined")
librephotos_backend   | ValueError: Function api.services.check_services is not defined
librephotos_backend   | 
librephotos_backend   | 22:32:05 [Q] INFO Enqueued [DjangORM] 16256
librephotos_backend   | 22:32:05 [Q] INFO Process-892f16f82c8d4aa496d9040878b6b0f4 created task romeo-six-stairway-west from schedule [1]
librephotos_backend   | 22:32:06 [Q] INFO Process-a133011e3b9d497c95c9837297f4cdec processing romeo-six-stairway-west 'api.services.check_services' [1]
librephotos_backend   | 22:32:06 [Q] ERROR Failed 'api.services.check_services' (romeo-six-stairway-west) - Function api.services.check_services is not defined : Traceback (most recent call last):
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django_q/worker.py", line 96, in worker
librephotos_backend   |     raise ValueError(f"Function {task['func']} is not defined")
librephotos_backend   | ValueError: Function api.services.check_services is not defined
librephotos_backend   | 
librephotos_backend   | 22:32:36 [Q] INFO Enqueued [DjangORM] 16257
librephotos_backend   | 22:32:36 [Q] INFO Process-892f16f82c8d4aa496d9040878b6b0f4 created task rugby-edward-emma-three from schedule [1]
librephotos_backend   | 22:32:36 [Q] INFO Process-a133011e3b9d497c95c9837297f4cdec processing rugby-edward-emma-three 'api.services.check_services' [1]
librephotos_backend   | 22:32:36 [Q] ERROR Failed 'api.services.check_services' (rugby-edward-emma-three) - Function api.services.check_services is not defined : Traceback (most recent call last):
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django_q/worker.py", line 96, in worker
librephotos_backend   |     raise ValueError(f"Function {task['func']} is not defined")
librephotos_backend   | ValueError: Function api.services.check_services is not defined
librephotos_backend   | 

Logs when do go to web UI and refresh browser

librephotos_proxy     | 192.168.0.100 - - [18/Aug/2024:22:43:59 +0000] "GET /api/rqavailable/ HTTP/1.1" 500 145 "https://photos.williamusic.com/admin" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36 Edg/127.0.0.0"
librephotos_proxy     | 192.168.0.100 - - [18/Aug/2024:22:44:00 +0000] "GET /api/dirtree/?path= HTTP/1.1" 200 666 "https://photos.williamusic.com/admin" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36 Edg/127.0.0.0"
librephotos_proxy     | 192.168.0.100 - - [18/Aug/2024:22:44:00 +0000] "GET /api/sitesettings HTTP/1.1" 200 201 "https://photos.williamusic.com/admin" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36 Edg/127.0.0.0"
librephotos_db        | 2024-08-18 22:44:00.080 UTC [7970] ERROR:  column api_longrunningjob.result does not exist at character 268
librephotos_db        | 2024-08-18 22:44:00.080 UTC [7970] STATEMENT:  SELECT "api_longrunningjob"."id", "api_longrunningjob"."job_type", "api_longrunningjob"."finished", "api_longrunningjob"."failed", "api_longrunningjob"."job_id", "api_longrunningjob"."queued_at", "api_longrunningjob"."started_at", "api_longrunningjob"."finished_at", "api_longrunningjob"."result", "api_longrunningjob"."started_by_id" FROM "api_longrunningjob" ORDER BY "api_longrunningjob"."started_at" DESC LIMIT 10
librephotos_backend   | Internal Server Error: /api/jobs/
librephotos_backend   | Traceback (most recent call last):
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/db/backends/utils.py", line 89, in _execute
librephotos_backend   |     return self.cursor.execute(sql, params)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/psycopg/cursor.py", line 732, in execute
librephotos_backend   |     raise ex.with_traceback(None)
librephotos_backend   | psycopg.errors.UndefinedColumn: column api_longrunningjob.result does not exist
librephotos_backend   | LINE 1: ..."started_at", "api_longrunningjob"."finished_at", "api_longr...
librephotos_backend   |                                                              ^
librephotos_backend   | 
librephotos_backend   | The above exception was the direct cause of the following exception:
librephotos_backend   | 
librephotos_backend   | Traceback (most recent call last):
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/core/handlers/exception.py", line 55, in inner
librephotos_backend   |     response = get_response(request)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/core/handlers/base.py", line 197, in _get_response
librephotos_backend   |     response = wrapped_callback(request, *callback_args, **callback_kwargs)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/views/decorators/csrf.py", line 56, in wrapper_view
librephotos_backend   |     return view_func(*args, **kwargs)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/rest_framework/viewsets.py", line 125, in view
librephotos_backend   |     return self.dispatch(request, *args, **kwargs)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/rest_framework/views.py", line 509, in dispatch
librephotos_backend   |     response = self.handle_exception(exc)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/rest_framework/views.py", line 469, in handle_exception
librephotos_backend   |     self.raise_uncaught_exception(exc)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/rest_framework/views.py", line 480, in raise_uncaught_exception
librephotos_backend   |     raise exc
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/rest_framework/views.py", line 506, in dispatch
librephotos_backend   |     response = handler(request, *args, **kwargs)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/rest_framework/mixins.py", line 40, in list
librephotos_backend   |     page = self.paginate_queryset(queryset)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/rest_framework/generics.py", line 171, in paginate_queryset
librephotos_backend   |     return self.paginator.paginate_queryset(queryset, self.request, view=self)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/rest_framework/pagination.py", line 216, in paginate_queryset
librephotos_backend   |     return list(self.page)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/core/paginator.py", line 174, in __len__
librephotos_backend   |     return len(self.object_list)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/db/models/query.py", line 380, in __len__
librephotos_backend   |     self._fetch_all()
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/db/models/query.py", line 1881, in _fetch_all
librephotos_backend   |     self._result_cache = list(self._iterable_class(self))
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/db/models/query.py", line 91, in __iter__
librephotos_backend   |     results = compiler.execute_sql(
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/db/models/sql/compiler.py", line 1562, in execute_sql
librephotos_backend   |     cursor.execute(sql, params)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/db/backends/utils.py", line 67, in execute
librephotos_backend   |     return self._execute_with_wrappers(
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/db/backends/utils.py", line 80, in _execute_with_wrappers
librephotos_backend   |     return executor(sql, params, many, context)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/db/backends/utils.py", line 84, in _execute
librephotos_backend   |     with self.db.wrap_database_errors:
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/db/utils.py", line 91, in __exit__
librephotos_backend   |     raise dj_exc_value.with_traceback(traceback) from exc_value
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django/db/backends/utils.py", line 89, in _execute
librephotos_backend   |     return self.cursor.execute(sql, params)
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/psycopg/cursor.py", line 732, in execute
librephotos_backend   |     raise ex.with_traceback(None)
librephotos_backend   | django.db.utils.ProgrammingError: column api_longrunningjob.result does not exist
librephotos_backend   | LINE 1: ..."started_at", "api_longrunningjob"."finished_at", "api_longr...
librephotos_backend   |                                                              ^
librephotos_proxy     | 192.168.0.100 - - [18/Aug/2024:22:44:00 +0000] "GET /api/jobs/?page_size=10&page=1 HTTP/1.1" 500 145 "https://photos.williamusic.com/admin" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36 Edg/127.0.0.0"
librephotos_proxy     | 192.168.0.100 - - [18/Aug/2024:22:44:00 +0000] "GET /api/user/1/ HTTP/1.1" 200 2611 "https://photos.williamusic.com/admin" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36 Edg/127.0.0.0"
librephotos_proxy     | 192.168.0.100 - - [18/Aug/2024:22:44:00 +0000] "GET /api/user/ HTTP/1.1" 200 10258 "https://photos.williamusic.com/admin" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36 Edg/127.0.0.0"
librephotos_proxy     | 192.168.0.100 - - [18/Aug/2024:22:44:01 +0000] "GET /api/serverstats HTTP/1.1" 200 5667 "https://photos.williamusic.com/admin" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36 Edg/127.0.0.0"
librephotos_proxy     | 192.168.0.100 - - [18/Aug/2024:22:44:02 +0000] "GET /api/searchtermexamples/ HTTP/1.1" 200 903 "https://photos.williamusic.com/admin" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36 Edg/127.0.0.0"
librephotos_backend   | 22:44:07 [Q] INFO Enqueued [DjangORM] 16270
librephotos_backend   | 22:44:07 [Q] INFO Process-892f16f82c8d4aa496d9040878b6b0f4 created task cola-river-asparagus-bakerloo from schedule [1]
librephotos_backend   | 22:44:07 [Q] INFO Process-a133011e3b9d497c95c9837297f4cdec processing cola-river-asparagus-bakerloo 'api.services.check_services' [1]
librephotos_backend   | 22:44:07 [Q] ERROR Failed 'api.services.check_services' (cola-river-asparagus-bakerloo) - Function api.services.check_services is not defined : Traceback (most recent call last):
librephotos_backend   |   File "/usr/local/lib/python3.10/dist-packages/django_q/worker.py", line 96, in worker
librephotos_backend   |     raise ValueError(f"Function {task['func']} is not defined")
librephotos_backend   | ValueError: Function api.services.check_services is not defined
librephotos_backend   | 

While running scan

I figured I'd run a scan to maybe restart the api

docker exec --user root librephotos_backend python3 manage.py scan
use SECRET_KEY from file
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/django/db/backends/utils.py", line 89, in _execute
    return self.cursor.execute(sql, params)
  File "/usr/local/lib/python3.10/dist-packages/psycopg/cursor.py", line 732, in execute
    raise ex.with_traceback(None)
psycopg.errors.UndefinedColumn: column "result" of relation "api_longrunningjob" does not exist
LINE 1: ...ob_id", "queued_at", "started_at", "finished_at", "result", ...
                                                             ^

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/code/manage.py", line 31, in <module>
    execute_from_command_line(sys.argv)
  File "/usr/local/lib/python3.10/dist-packages/django/core/management/__init__.py", line 442, in execute_from_command_line
    utility.execute()
  File "/usr/local/lib/python3.10/dist-packages/django/core/management/__init__.py", line 436, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/usr/local/lib/python3.10/dist-packages/django/core/management/base.py", line 412, in run_from_argv
    self.execute(*args, **cmd_options)
  File "/usr/local/lib/python3.10/dist-packages/django/core/management/base.py", line 458, in execute
    output = self.handle(*args, **options)
  File "/code/api/management/commands/scan.py", line 55, in handle
    scan_photos(
  File "/code/api/directory_watcher.py", line 329, in scan_photos
    lrj = LongRunningJob.objects.create(
  File "/usr/local/lib/python3.10/dist-packages/django/db/models/manager.py", line 87, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/usr/local/lib/python3.10/dist-packages/django/db/models/query.py", line 658, in create
    obj.save(force_insert=True, using=self.db)
  File "/usr/local/lib/python3.10/dist-packages/django/db/models/base.py", line 814, in save
    self.save_base(
  File "/usr/local/lib/python3.10/dist-packages/django/db/models/base.py", line 877, in save_base
    updated = self._save_table(
  File "/usr/local/lib/python3.10/dist-packages/django/db/models/base.py", line 1020, in _save_table
    results = self._do_insert(
  File "/usr/local/lib/python3.10/dist-packages/django/db/models/base.py", line 1061, in _do_insert
    return manager._insert(
  File "/usr/local/lib/python3.10/dist-packages/django/db/models/manager.py", line 87, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/usr/local/lib/python3.10/dist-packages/django/db/models/query.py", line 1805, in _insert
    return query.get_compiler(using=using).execute_sql(returning_fields)
  File "/usr/local/lib/python3.10/dist-packages/django/db/models/sql/compiler.py", line 1822, in execute_sql
    cursor.execute(sql, params)
  File "/usr/local/lib/python3.10/dist-packages/django/db/backends/utils.py", line 67, in execute
    return self._execute_with_wrappers(
  File "/usr/local/lib/python3.10/dist-packages/django/db/backends/utils.py", line 80, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/usr/local/lib/python3.10/dist-packages/django/db/backends/utils.py", line 84, in _execute
    with self.db.wrap_database_errors:
  File "/usr/local/lib/python3.10/dist-packages/django/db/utils.py", line 91, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/usr/local/lib/python3.10/dist-packages/django/db/backends/utils.py", line 89, in _execute
    return self.cursor.execute(sql, params)
  File "/usr/local/lib/python3.10/dist-packages/psycopg/cursor.py", line 732, in execute
    raise ex.with_traceback(None)
django.db.utils.ProgrammingError: column "result" of relation "api_longrunningjob" does not exist
LINE 1: ...ob_id", "queued_at", "started_at", "finished_at", "result", ...

Workers UI

Looks like the workers are busy but I don't know anything more than busy.... This stack was previously using the non-gpu version if that is causing any issue. image

derneuere commented 3 months ago
LINE 1: ...ob_id", "queued_at", "started_at", "finished_at", "result", ...

These errors are the result of the librephotos and librephotos-gpu image being out of sync. The release job did not work correctly the last couple of releases. Can you switch to the dev tag with the librephotos-gpu image?

wchorski commented 3 months ago
LINE 1: ...ob_id", "queued_at", "started_at", "finished_at", "result", ...

These errors are the result of the librephotos and librephotos-gpu image being out of sync. The release job did not work correctly the last couple of releases. Can you switch to the dev tag with the librephotos-gpu image?

I've switched over to the dev tag and all is working well (I moved all containers over to dev branch)

Also, there was a bug with the login session becoming invalid when switching to a new tab / closing opening browser that is not here on the dev branch.

Should I close this issue, or should I keep it open until it's merged with latest?

derneuere commented 2 months ago

New release is now out, this should be fixed :)

Login session is managed in the frontend container and that should be fixed now too