search

jonaswinkler / paperless-ng

A supercharged version of paperless: scan, index and archive all your physical documents
https://paperless-ng.readthedocs.io/en/latest/
GNU General Public License v3.0
5.38k stars 354 forks source link

[BUG] Scheduled tasks not waiting for Redis to start #1561

Open arifer612 opened 2 years ago

arifer612 commented 2 years ago

Describe the bug Scheduled tasks in paperless-ng will just plain stop working if Redis is not ready for querying at launch. This appears to be the case because the database is still starting up. Everything is fixed when I restart the container, or if I intentionally wait for a minute after Redis is spun up before spinning up the paperles--ng container.

To Reproduce Steps to reproduce the behavior:

  1. Spin up Redis container
  2. Spin up paperless-ng container
  3. Wait for scheduled tasks to run
  4. Check logs, see redis.exceptions.BusyLoadingError: Redis is loading the dataset in memory error.
  5. Restart paperless-ng container
  6. Everything works

Expected behavior paperless-ng to retry connecting to Redis after the BusyLoadingError instead of giving up completely.

Screenshots If applicable, add screenshots to help explain your problem.

Webserver logs

today at 11:34:54 PM23:34:54 [Q] INFO Q Cluster pasta-lemon-lithium-thirteen starting.
today at 11:34:54 PM23:34:54 [Q] ERROR Can not connect to Redis server.
today at 11:34:54 PMProcess Process-1:
today at 11:34:54 PMTraceback (most recent call last):
today at 11:34:54 PM  File "/usr/local/lib/python3.9/multiprocessing/process.py", line 315, in _bootstrap
today at 11:34:54 PM    self.run()
today at 11:34:54 PM  File "/usr/local/lib/python3.9/multiprocessing/process.py", line 108, in run
today at 11:34:54 PM    self._target(*self._args, **self._kwargs)
today at 11:34:54 PM  File "/usr/local/lib/python3.9/site-packages/django_q/cluster.py", line 168, in __init__
today at 11:34:54 PM    self.start()
today at 11:34:54 PM  File "/usr/local/lib/python3.9/site-packages/django_q/cluster.py", line 171, in start
today at 11:34:54 PM    self.broker.ping()
today at 11:34:54 PM  File "/usr/local/lib/python3.9/site-packages/django_q/brokers/redis_broker.py", line 39, in ping
today at 11:34:54 PM    raise e
today at 11:34:54 PM  File "/usr/local/lib/python3.9/site-packages/django_q/brokers/redis_broker.py", line 36, in ping
today at 11:34:54 PM    return self.connection.ping()
today at 11:34:54 PM  File "/usr/local/lib/python3.9/site-packages/redis/client.py", line 1378, in ping
today at 11:34:54 PM    return self.execute_command('PING')
today at 11:34:54 PM  File "/usr/local/lib/python3.9/site-packages/redis/client.py", line 901, in execute_command
today at 11:34:54 PM    return self.parse_response(conn, command_name, **options)
today at 11:34:54 PM  File "/usr/local/lib/python3.9/site-packages/redis/client.py", line 915, in parse_response
today at 11:34:54 PM    response = connection.read_response()
today at 11:34:54 PM  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 739, in read_response
today at 11:34:54 PM    response = self._parser.read_response()
today at 11:34:54 PM  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 484, in read_response
today at 11:34:54 PM    raise response
today at 11:34:54 PMredis.exceptions.BusyLoadingError: Redis is loading the dataset in memory
today at 11:36:41 PM[2022-01-18 23:36:41 +0800] [286] [CRITICAL] WORKER TIMEOUT (pid:289)
today at 11:36:41 PM[2022-01-18 23:36:41 +0800] [286] [WARNING] Worker with pid 289 was terminated due to signal 6

Relevant information

moorgrove commented 2 years ago

I have the same issue with a new clean installation with the Docker image.

Paperless-ng docker container starting...

Creating directory /tmp/paperless

Adjusting permissions of paperless files. This may take a while.

Apply database migrations...

Operations to perform:

  Apply all migrations: admin, auth, authtoken, contenttypes, django_q, documents, paperless_mail, sessions

Running migrations:

  No migrations to apply.

Executing /usr/local/bin/supervisord -c /etc/supervisord.conf

2022-01-24 11:13:42,531 INFO Set uid to user 0 succeeded

2022-01-24 11:13:42,533 INFO supervisord started with pid 1

2022-01-24 11:13:43,536 INFO spawned: 'consumer' with pid 34

2022-01-24 11:13:43,539 INFO spawned: 'gunicorn' with pid 35

2022-01-24 11:13:43,541 INFO spawned: 'scheduler' with pid 36

[2022-01-24 11:13:43 +0000] [35] [INFO] Starting gunicorn 20.1.0

[2022-01-24 11:13:43 +0000] [35] [INFO] Listening at: http://0.0.0.0:8000 (35)

[2022-01-24 11:13:43 +0000] [35] [INFO] Using worker: paperless.workers.ConfigurableWorker

[2022-01-24 11:13:43 +0000] [35] [INFO] Server is ready. Spawning workers

11:13:44 [Q] INFO Q Cluster edward-nineteen-carbon-sink starting.

2022-01-24 11:13:44,644 INFO success: consumer entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

2022-01-24 11:13:44,645 INFO success: gunicorn entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

2022-01-24 11:13:44,645 INFO success: scheduler entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

11:13:44 [Q] ERROR Can not connect to Redis server.

Process Process-1:

Traceback (most recent call last):

  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 559, in connect

    sock = self._connect()

  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 615, in _connect

    raise err

  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 603, in _connect

    sock.connect(socket_address)

OSError: [Errno 99] Cannot assign requested address

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "/usr/local/lib/python3.9/multiprocessing/process.py", line 315, in _bootstrap

    self.run()

  File "/usr/local/lib/python3.9/multiprocessing/process.py", line 108, in run

    self._target(*self._args, **self._kwargs)

  File "/usr/local/lib/python3.9/site-packages/django_q/cluster.py", line 168, in __init__

    self.start()

  File "/usr/local/lib/python3.9/site-packages/django_q/cluster.py", line 171, in start

    self.broker.ping()

  File "/usr/local/lib/python3.9/site-packages/django_q/brokers/redis_broker.py", line 39, in ping

    raise e

  File "/usr/local/lib/python3.9/site-packages/django_q/brokers/redis_broker.py", line 36, in ping

    return self.connection.ping()

  File "/usr/local/lib/python3.9/site-packages/redis/client.py", line 1378, in ping

    return self.execute_command('PING')

  File "/usr/local/lib/python3.9/site-packages/redis/client.py", line 898, in execute_command

    conn = self.connection or pool.get_connection(command_name, **options)

  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 1192, in get_connection

    connection.connect()

  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 563, in connect

    raise ConnectionError(self._error_message(e))

redis.exceptions.ConnectionError: Error 99 connecting to localhost:6379. Cannot assign requested address.

[2022-01-24 11:13:44,661] [INFO] [paperless.management.consumer] Using inotify to watch directory for changes: /usr/src/paperless/src/../consume
moorgrove commented 2 years ago

Solved my problem by deploy the stack instead of just the container.

https://github.com/jonaswinkler/paperless-ng/blob/master/docker/compose/docker-compose.portainer.yml

arifer612 commented 2 years ago

Having it deployed as a stack does ensure that paperless-ng gets initialised after redis is spun up but it does not mean that the problem is solved. I prefer not to have to stack my databases with my apps since that will take a lot of resources when I have a large number of services. Moreover, paperless-ng should also be able to properly handle failed database queries if the database is down instead of just outright failing.

nightred commented 2 years ago

Having it deployed as a stack does ensure that paperless-ng gets initialised after redis is spun up but it does not mean that the problem is solved.

I agree that the isue is not resolved. the application should make attempts to reconnect to the database after a fair delay to allow the databse to resume. This is an issue for any database restarts, backups or network hickups, the service is not reciliant when it comes to any blips and needs to be restarted.

morremeyer commented 2 years ago

I consider this a bug too, because while in a docker stack it might be easily resolved, running it e.g. in Kubernetes where the components are completely decoupled there is no sensible way of starting paperless after redis.

arifer612 commented 2 years ago

I guess we should wait for the new paperless organisation to be set up before looking to see what we can do about it. If the new organisation does accept PRs, then I can probably take one of my days off to inspect the issue.

I'm guessing that adding a simple catch on the redis.exceptions.BusyLoadingError should be sufficient to fix the problem.

shamoon commented 2 years ago

Definitely accepting PRs :) https://github.com/paperless-ngx/paperless-ngx

arifer612 commented 2 years ago

@shamoon That's awesome! I'll go load up the new project and see if I can make time to work on what I talked about!