Unauthorized: /api/rqavailable/

[gregbert42]

Backend continuously giving "unauthorized" messages like this (every few sec)

The bigger problem is that whenever i give the worker something to do (e.g., scan photos) it never completes the job. (after adding the photos)

Unauthorized: /api/jobs/ Unauthorized: /api/sitesettings/ Unauthorized: /api/jobs/ Unauthorized: /api/user/ Unauthorized: /api/dirtree/ Unauthorized: /api/jobs/ Unauthorized: /api/sitesettings/ Unauthorized: /api/jobs/ Unauthorized: /api/user/ Unauthorized: /api/dirtree/ Unauthorized: /api/rqavailable/ Unauthorized: /api/rqavailable/ Unauthorized: /api/stats/ Unauthorized: /api/sitesettings/ Unauthorized: /api/user/1/ Unauthorized: /api/nextcloud/listdir/ Unauthorized: /api/stats/ Unauthorized: /api/jobs/ Unauthorized: /api/stats/ Unauthorized: /api/sitesettings/ Unauthorized: /api/user/1/ Unauthorized: /api/nextcloud/listdir/ Unauthorized: /api/stats/ Unauthorized: /api/jobs/

[guysoft]

Try logging out and logging in again, its a bug. We should bring up a huge "please log in" message in the frontend. And also add a "remember me" button. Please re-open this bug at: https://github.com/hooram/ownphotos-frontend I am not a good UI developer so would appreciate help here.

[hooram]

This might be because the expiration of the access token is set to a short period of time (tens of seconds or so) and for every non-login 400 response the front end tries to refresh the token.

[guysoft]

@hooram It happens to me when I

1. login
2. stop the container
3. start the container.

Regardless, for what ever reason, if you get "Unauthorized" in the API it should physically show on the screen, not just show the worker is busy.

[gregbert42]

i've redownloaded the docker-compose.yaml, deleted all existing volumes, images, etc before docker-compose up'ing the new stuff.

still getting 'not found' on /apis , but eventually also this error after being stuck on still 'scanning' for 30 minutes (after adding the scan directory, etc).

5505it [04:41, 13.57it/s]Error in directory scan, got exception:
connection already closed
Traceback (most recent call last):
  File "/venv/lib/python3.5/site-packages/django/db/backends/base/base.py", line 234, in _cursor
    return self._prepare_cursor(self.create_cursor(name))
  File "/venv/lib/python3.5/site-packages/django/db/backends/postgresql/base.py", line 222, in create_cursor
    cursor = self.connection.cursor()
psycopg2.InterfaceError: connection already closed

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

Traceback (most recent call last): File "/code/api/directory_watcher.py", line 52, in handle_new_image image_hash=image_hash).exists() File "/venv/lib/python3.5/site-packages/django/db/models/query.py", line 718, in exists return self.query.has_results(using=self.db) File "/venv/lib/python3.5/site-packages/django/db/models/sql/query.py", line 516, in has_results return compiler.has_results() File "/venv/lib/python3.5/site-packages/django/db/models/sql/compiler.py", line 1035, in has_results return bool(self.execute_sql(SINGLE)) File "/venv/lib/python3.5/site-packages/django/db/models/sql/compiler.py", line 1063, in execute_sql cursor = self.connection.cursor() File "/venv/lib/python3.5/site-packages/django/db/backends/base/base.py", line 255, in cursor return self._cursor() File "/venv/lib/python3.5/site-packages/django/db/backends/base/base.py", line 234, in _cursor return self._prepare_cursor(self.create_cursor(name)) File "/venv/lib/python3.5/site-packages/django/db/utils.py", line 89, in exit raise dj_exc_value.with_traceback(traceback) from exc_value File "/venv/lib/python3.5/site-packages/django/db/backends/base/base.py", line 234, in _cursor return self._prepare_cursor(self.create_cursor(name)) File "/venv/lib/python3.5/site-packages/django/db/backends/postgresql/base.py", line 222, in create_cursor cursor = self.connection.cursor() django.db.utils.InterfaceError: connection already closed

[gregbert42]

relatedly - how does one force end a 'job'. they seem to go on forever, even when they are actually not doing anything...

[guysoft]

@gregbert42 Might be related to: https://github.com/hooram/ownphotos/issues/48

You can follow instruction to use adminer and look at your db directly.

[gregbert42]

Using adminer, i discovered that my scan of photos is causing the backend to crash, but it leaves the entry in the postgres database under api_longrunningjob. I think you are right that this is related to #48 - but then the crash is also a problem in the first place. Note in the below that it attempts to move the job to the failed queue.

django.db.utils.OperationalError: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
18:36:55 Invoking exception handler <bound method Worker.move_to_failed_queue of <rq.worker.Worker object at 0x7f703811d3c8>>
18:36:55 Moving job to 'failed' queue
18:36:55 Sent heartbeat to prevent worker timeout. Next one should arrive within 420 seconds.
18:36:55 Sent heartbeat to prevent worker timeout. Next one should arrive within 420 seconds.
18:36:55 *** Listening on default...
18:36:55 Sent heartbeat to prevent worker timeout. Next one should arrive within 420 seconds.
Unauthorized: /api/rqavailable/
Unauthorized: /api/rqavailable/

[guysoft]

a workaround would be to delete that row. I think a simple sql on ststup should fix it, I am just more of a sqlalchamy/flask person and not sure how to code itit in django.

[gregbert42]

Yes, deleting that row makes the 'worker' available to me again. But the main problem is that ownphotos crashes after scanning 100-500 photos. Having 28,000 photos to scan, i think this may be a problem! @hooram please let me know what information i can provide to help here.

[guysoft]

Output of the log files in /code/logs in the ownphotos-backend container, use the latest image because I added something that makes it output more info.

[gregbert42]

Started with fresh everything...

started the new scan job

pooped out after importing ~70 photos

Here are the logs: https://www.dropbox.com/sh/f6364yjdjsnszgc/AACfOTYRN6b_kWlnMEP6Ud07a?dl=0

[guysoft]

Ok two things I can see in the logs.

The first is in ownphotos.log:

2018-12-27 19:17:34,700 : directory_watcher.py : handle_new_image : 121 : INFO : adding to AlbumThing took 0.59
2018-12-27 19:17:34,701 : directory_watcher.py : handle_new_image : 138 : ERROR : Could not load image /data/iPhone_Pictures_Alpha-Aug2013/IMG_0998.JPG. reason: UnboundLocalError("local variable 'added_photo_count' referenced before assignment",)
2018-12-27 19:17:34,891 : directory_watcher.py : scan_photos : 187 : INFO : Added 0/52804 photos

You might be using and old one, suggest you run

sudo docker pull guysoft/ownphotos

Or

sudo docker pull hooram/ownphotos

And then

sudo docker-compose up -d

So you have the lastest image without that bug. The error refers to this line: https://github.com/hooram/ownphotos/blob/dev/api/directory_watcher.py#L123 which changed recently

The second is in the DB:

psycopg2.DatabaseError: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.


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

Traceback (most recent call last):
  File "/code/api/directory_watcher.py", line 189, in scan_photos
    lrj = LongRunningJob.objects.get(job_id=rq.get_current_job().id)
  File "/venv/lib/python3.5/site-packages/django/db/models/manager.py", line 82, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/venv/lib/python3.5/site-packages/django/db/models/query.py", line 393, in get
    num = len(clone)
  File "/venv/lib/python3.5/site-packages/django/db/models/query.py", line 250, in __len__
    self._fetch_all()
  File "/venv/lib/python3.5/site-packages/django/db/models/query.py", line 1186, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
  File "/venv/lib/python3.5/site-packages/django/db/models/query.py", line 54, in __iter__
    results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)
  File "/venv/lib/python3.5/site-packages/django/db/models/sql/compiler.py", line 1065, in execute_sql
    cursor.execute(sql, params)
  File "/venv/lib/python3.5/site-packages/django/db/backends/utils.py", line 100, in execute
    return super().execute(sql, params)
  File "/venv/lib/python3.5/site-packages/django/db/backends/utils.py", line 68, in execute
    return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
  File "/venv/lib/python3.5/site-packages/django/db/backends/utils.py", line 77, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/venv/lib/python3.5/site-packages/django/db/backends/utils.py", line 85, in _execute
    return self.cursor.execute(sql, params)
  File "/venv/lib/python3.5/site-packages/django/db/utils.py", line 89, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/venv/lib/python3.5/site-packages/django/db/backends/utils.py", line 85, in _execute
    return self.cursor.execute(sql, params)
django.db.utils.DatabaseError: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/venv/lib/python3.5/site-packages/django/db/backends/base/base.py", line 234, in _cursor
    return self._prepare_cursor(self.create_cursor(name))
  File "/venv/lib/python3.5/site-packages/django/db/backends/postgresql/base.py", line 222, in create_cursor
    cursor = self.connection.cursor()
psycopg2.InterfaceError: connection already closed

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

Traceback (most recent call last):
  File "/venv/lib/python3.5/site-packages/rq/worker.py", line 793, in perform_job
    rv = job.perform()
  File "/venv/lib/python3.5/site-packages/rq/job.py", line 599, in perform
    self._result = self._execute()
  File "/venv/lib/python3.5/site-packages/rq/job.py", line 605, in _execute
    return self.func(*self.args, **self.kwargs)
  File "/code/api/directory_watcher.py", line 196, in scan_photos
    lrj = LongRunningJob.objects.get(job_id=rq.get_current_job().id)
  File "/venv/lib/python3.5/site-packages/django/db/models/manager.py", line 82, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/venv/lib/python3.5/site-packages/django/db/models/query.py", line 393, in get
    num = len(clone)
  File "/venv/lib/python3.5/site-packages/django/db/models/query.py", line 250, in __len__
    self._fetch_all()
  File "/venv/lib/python3.5/site-packages/django/db/models/query.py", line 1186, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
  File "/venv/lib/python3.5/site-packages/django/db/models/query.py", line 54, in __iter__
    results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)
  File "/venv/lib/python3.5/site-packages/django/db/models/sql/compiler.py", line 1063, in execute_sql
    cursor = self.connection.cursor()
  File "/venv/lib/python3.5/site-packages/django/db/backends/base/base.py", line 255, in cursor
    return self._cursor()
  File "/venv/lib/python3.5/site-packages/django/db/backends/base/base.py", line 234, in _cursor
    return self._prepare_cursor(self.create_cursor(name))
  File "/venv/lib/python3.5/site-packages/django/db/utils.py", line 89, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/venv/lib/python3.5/site-packages/django/db/backends/base/base.py", line 234, in _cursor
    return self._prepare_cursor(self.create_cursor(name))
  File "/venv/lib/python3.5/site-packages/django/db/backends/postgresql/base.py", line 222, in create_cursor
    cursor = self.connection.cursor()
django.db.utils.InterfaceError: connection already closed
19:17:34 Invoking exception handler <bound method Worker.move_to_failed_queue of <rq.worker.Worker object at 0x7f3365995b00>>
19:17:34 Moving job to 'failed' queue
19:17:35 Sent heartbeat to prevent worker timeout. Next one should arrive within 420 seconds.
19:17:35 Sent heartbeat to prevent worker timeout. Next one should arrive within 420 seconds.
19:17:35 *** Listening on default...
19:17:35 Sent heartbeat to prevent worker timeout. 

I am not sure what is goign on with your db, I suggest you recreate it. Make sure to delete the volume with sudo docker volume prune after you run sudo docker-compose stop ; sudo docker-compose rm -f

[danielsjf]

I had the same issue as @gregbert42 had, and I also managed to remove those rows to get the worker back.

Unfortunately this doesn't solve my other API not found issue as mentioned in the initial post. Is there any way to debug this? The log only mentions:

Not Found: /api

If I go to localhost:3000/api, I see the following.

I tried login in and out as suggested above, but that doesn't change anything. The container is also running (I checked all of them).

I also tried the Python package, which also can't find the API.