Koed00 / django-q

A multiprocessing distributed task queue for Django
https://django-q.readthedocs.org
MIT License
1.83k stars 285 forks source link

psycopg2.OperationalError: SSL error: sslv3 alert bad record mac #484

Open 9126consulting opened 3 years ago

9126consulting commented 3 years ago

Operating System:

Linux ip-10-2-4-177 5.3.0-1008-aws #9-Ubuntu SMP Fri Nov 15 07:13:59 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Versions:

Python 3.7.5 django-q==1.3.3 psycopg2-binary==2.8.5

Setting:

Q_CLUSTER = { 'name': 'DjangORM', 'workers': 4, 'recycle': 5, 'timeout': None, 'retry': 86400, 'queue_limit': 4, 'bulk': 1, 'orm': 'default', 'catch_up': False, 'poll': 1.0 }

Error LOG

08:20:52 [Q] INFO Q Cluster early-hot-neptune-neptune running. --- Logging error --- Traceback (most recent call last): File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute return self.cursor.execute(sql, params) psycopg2.OperationalError: SSL error: sslv3 alert bad record mac

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

Traceback (most recent call last): File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 332, in pusher task_set = broker.dequeue() File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/brokers/orm.py", line 67, in dequeue if tasks: File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 280, in bool self._fetch_all() File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 1261, in _fetch_all self._result_cache = list(self._iterable_class(self)) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 57, in iter results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/models/sql/compiler.py", line 1152, in execute_sql cursor.execute(sql, params) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 68, in execute return self._execute_with_wrappers(sql, params, many=False, executor=self._execute) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 77, in _execute_with_wrappers return executor(sql, params, many, context) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute return self.cursor.execute(sql, params) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/utils.py", line 90, in exit raise dj_exc_value.with_traceback(traceback) from exc_value File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute return self.cursor.execute(sql, params) django.db.utils.OperationalError: SSL error: sslv3 alert bad record mac

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/usr/lib/python3.7/logging/init.py", line 1025, in emit msg = self.format(record) File "/usr/lib/python3.7/logging/init.py", line 869, in format return fmt.format(record) File "/usr/lib/python3.7/logging/init.py", line 608, in format record.message = record.getMessage() File "/usr/lib/python3.7/logging/init.py", line 369, in getMessage msg = msg % self.args TypeError: not all arguments converted during string formatting Call stack: File "manage.py", line 10, in execute_from_command_line(sys.argv) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/core/management/init.py", line 401, in execute_from_command_line utility.execute() File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/core/management/init.py", line 395, in execute self.fetch_command(subcommand).run_from_argv(self.argv) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/core/management/base.py", line 328, in run_from_argv self.execute(*args, cmd_options) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/core/management/base.py", line 369, in execute output = self.handle(*args, *options) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/management/commands/qcluster.py", line 22, in handle q.start() File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 67, in start self.sentinel.start() File "/usr/lib/python3.7/multiprocessing/process.py", line 112, in start self._popen = self._Popen(self) File "/usr/lib/python3.7/multiprocessing/context.py", line 223, in _Popen return _default_context.get_context().Process._Popen(process_obj) File "/usr/lib/python3.7/multiprocessing/context.py", line 277, in _Popen return Popen(process_obj) File "/usr/lib/python3.7/multiprocessing/popen_fork.py", line 20, in init self._launch(process_obj) File "/usr/lib/python3.7/multiprocessing/popen_fork.py", line 74, in _launch code = process_obj._bootstrap() File "/usr/lib/python3.7/multiprocessing/process.py", line 297, in _bootstrap self.run() File "/usr/lib/python3.7/multiprocessing/process.py", line 99, in run self._target(self._args, self._kwargs) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 157, in init self.start() File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 161, in start self.spawn_cluster() File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 235, in spawn_cluster self.pusher = self.spawn_pusher() File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 190, in spawn_pusher return self.spawn_process(pusher, self.task_queue, self.event_out, self.broker) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 186, in spawn_process p.start() File "/usr/lib/python3.7/multiprocessing/process.py", line 112, in start self._popen = self._Popen(self) File "/usr/lib/python3.7/multiprocessing/context.py", line 223, in _Popen return _default_context.get_context().Process._Popen(process_obj) File "/usr/lib/python3.7/multiprocessing/context.py", line 277, in _Popen return Popen(process_obj) File "/usr/lib/python3.7/multiprocessing/popen_fork.py", line 20, in init self._launch(process_obj) File "/usr/lib/python3.7/multiprocessing/popen_fork.py", line 74, in _launch code = process_obj._bootstrap() File "/usr/lib/python3.7/multiprocessing/process.py", line 297, in _bootstrap self.run() File "/usr/lib/python3.7/multiprocessing/process.py", line 99, in run self._target(*self._args, **self._kwargs) File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 334, in pusher logger.error(e, traceback.format_exc()) Message: OperationalError('SSL error: sslv3 alert bad record mac\n') Arguments: ('Traceback (most recent call last):\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute\n return self.cursor.execute(sql, params)\npsycopg2.OperationalError: SSL error: sslv3 alert bad record mac\n\n\nThe above exception was the direct cause of the following exception:\n\nTraceback (most recent call last):\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 332, in pusher\n task_set = broker.dequeue()\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django_q/brokers/orm.py", line 67, in dequeue\n if tasks:\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 280, in bool\n self._fetch_all()\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 1261, in _fetch_all\n self._result_cache = list(self._iterable_class(self))\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 57, in iter\n results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/models/sql/compiler.py", line 1152, in execute_sql\n cursor.execute(sql, params)\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 68, in execute\n return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 77, in _execute_with_wrappers\n return executor(sql, params, many, context)\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute\n return self.cursor.execute(sql, params)\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/utils.py", line 90, in exit\n raise dj_exc_value.with_traceback(traceback) from exc_value\n File "/home/ubuntu/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute\n return self.cursor.execute(sql, params)\ndjango.db.utils.OperationalError: SSL error: sslv3 alert bad record mac\n\n',) ^C08:20:59 [Q] INFO Q Cluster early-hot-neptune-neptune stopping.

Workaround:

using Django-q==1.0.2

9126consulting commented 3 years ago

Disabling SSL results in:

20:18:31 [Q] INFO Process-1:7 pushing tasks at 12124 --- Logging error --- Traceback (most recent call last): File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute return self.cursor.execute(sql, params) psycopg2.OperationalError: 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 "/home/charry/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 332, in pusher task_set = broker.dequeue() File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/brokers/orm.py", line 67, in dequeue if tasks: File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 280, in bool self._fetch_all() File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 1261, in _fetch_all self._result_cache = list(self._iterable_class(self)) File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 57, in iter results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size) File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/models/sql/compiler.py", line 1152, in execute_sql cursor.execute(sql, params) File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 68, in execute return self._execute_with_wrappers(sql, params, many=False, executor=self._execute) File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 77, in _execute_with_wrappers return executor(sql, params, many, context) File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute return self.cursor.execute(sql, params) File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/utils.py", line 90, in exit raise dj_exc_value.with_traceback(traceback) from exc_value File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute return self.cursor.execute(sql, params) django.db.utils.OperationalError: 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 "/usr/lib/python3.7/logging/init.py", line 1034, in emit msg = self.format(record) File "/usr/lib/python3.7/logging/init.py", line 880, in format return fmt.format(record) File "/usr/lib/python3.7/logging/init.py", line 619, in format record.message = record.getMessage() File "/usr/lib/python3.7/logging/init.py", line 380, in getMessage msg = msg % self.args TypeError: not all arguments converted during string formatting Call stack: File "manage.py", line 10, in execute_from_command_line(sys.argv) File "/home/charry/charryenv/lib/python3.7/site-packages/django/core/management/init.py", line 401, in execute_from_command_line utility.execute() File "/home/charry/charryenv/lib/python3.7/site-packages/django/core/management/init.py", line 395, in execute self.fetch_command(subcommand).run_from_argv(self.argv) File "/home/charry/charryenv/lib/python3.7/site-packages/django/core/management/base.py", line 328, in run_from_argv self.execute(*args, cmd_options) File "/home/charry/charryenv/lib/python3.7/site-packages/django/core/management/base.py", line 369, in execute output = self.handle(*args, *options) File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/management/commands/qcluster.py", line 22, in handle q.start() File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 67, in start self.sentinel.start() File "/usr/lib/python3.7/multiprocessing/process.py", line 112, in start self._popen = self._Popen(self) File "/usr/lib/python3.7/multiprocessing/context.py", line 223, in _Popen return _default_context.get_context().Process._Popen(process_obj) File "/usr/lib/python3.7/multiprocessing/context.py", line 277, in _Popen return Popen(process_obj) File "/usr/lib/python3.7/multiprocessing/popen_fork.py", line 20, in init self._launch(process_obj) File "/usr/lib/python3.7/multiprocessing/popen_fork.py", line 74, in _launch code = process_obj._bootstrap() File "/usr/lib/python3.7/multiprocessing/process.py", line 297, in _bootstrap self.run() File "/usr/lib/python3.7/multiprocessing/process.py", line 99, in run self._target(self._args, self._kwargs) File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 157, in init self.start() File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 162, in start self.guard() File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 268, in guard self.reincarnate(self.pusher) File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 210, in reincarnate self.pusher = self.spawn_pusher() File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 190, in spawn_pusher return self.spawn_process(pusher, self.task_queue, self.event_out, self.broker) File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 186, in spawn_process p.start() File "/usr/lib/python3.7/multiprocessing/process.py", line 112, in start self._popen = self._Popen(self) File "/usr/lib/python3.7/multiprocessing/context.py", line 223, in _Popen return _default_context.get_context().Process._Popen(process_obj) File "/usr/lib/python3.7/multiprocessing/context.py", line 277, in _Popen return Popen(process_obj) File "/usr/lib/python3.7/multiprocessing/popen_fork.py", line 20, in init self._launch(process_obj) File "/usr/lib/python3.7/multiprocessing/popen_fork.py", line 74, in _launch code = process_obj._bootstrap() File "/usr/lib/python3.7/multiprocessing/process.py", line 297, in _bootstrap self.run() File "/usr/lib/python3.7/multiprocessing/process.py", line 99, in run self._target(*self._args, **self._kwargs) File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 334, in pusher logger.error(e, traceback.format_exc()) Message: OperationalError('server closed the connection unexpectedly\n\tThis probably means the server terminated abnormally\n\tbefore or while processing the request.\n') Arguments: ('Traceback (most recent call last):\n File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute\n return self.cursor.execute(sql, params)\npsycopg2.OperationalError: server closed the connection unexpectedly\n\tThis probably means the server terminated abnormally\n\tbefore or while processing the request.\n\n\nThe above exception was the direct cause of the following exception:\n\nTraceback (most recent call last):\n File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/cluster.py", line 332, in pusher\n task_set = broker.dequeue()\n File "/home/charry/charryenv/lib/python3.7/site-packages/django_q/brokers/orm.py", line 67, in dequeue\n if tasks:\n File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 280, in bool\n self._fetch_all()\n File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 1261, in _fetch_all\n self._result_cache = list(self._iterable_class(self))\n File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/models/query.py", line 57, in iter\n results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)\n File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/models/sql/compiler.py", line 1152, in execute_sql\n cursor.execute(sql, params)\n File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 68, in execute\n return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)\n File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 77, in _execute_with_wrappers\n return executor(sql, params, many, context)\n File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute\n return self.cursor.execute(sql, params)\n File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/utils.py", line 90, in exit\n raise dj_exc_value.with_traceback(traceback) from exc_value\n File "/home/charry/charryenv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute\n return self.cursor.execute(sql, params)\ndjango.db.utils.OperationalError: server closed the connection unexpectedly\n\tThis probably means the server terminated abnormally\n\tbefore or while processing the request.\n\n',) ^C20:18:33 [Q] INFO Q Cluster sweet-louisiana-nebraska-triple stopping.

9126consulting commented 3 years ago

Workaround for Django-Q 1.3.3

Do not set CONN_MAX_AGE in your database configuration and Django-q 1.3.3 will run.

New Issue

I guess Django-Q is unable to update it's own tables. My scheduled task starts again and again without any issue.

21:22:45 [Q] INFO Q Cluster mars-delta-alpha-emma running. 21:23:15 [Q] INFO Enqueued 87828 21:23:15 [Q] INFO Process-1 created a task from schedule [4] 21:23:15 [Q] ERROR connection already closed 21:23:17 [Q] INFO Process-1:1 processing [snake-spring-five-quiet] 21:23:18 [Q] INFO Process-1:1 stopped doing work 21:23:18 [Q] INFO recycled worker Process-1:1 21:23:18 [Q] INFO Process-1:7 ready for work at 12579 21:23:19 [Q] INFO Processed [snake-spring-five-quiet] 21:23:46 [Q] INFO Enqueued 87829 21:23:46 [Q] INFO Process-1 created a task from schedule [4] 21:23:46 [Q] ERROR connection already closed 21:23:47 [Q] INFO Process-1:2 processing [hot-johnny-texas-xray] 21:23:48 [Q] INFO Process-1:2 stopped doing work 21:23:49 [Q] INFO recycled worker Process-1:2 21:23:49 [Q] INFO Process-1:8 ready for work at 12581 21:23:49 [Q] INFO Processed [hot-johnny-texas-xray]

9126consulting commented 3 years ago

Here's a debug log output:

Oct 26 22:17:04 pyapp INFO django-q.cluster:642 Process-1 created a task from schedule [4] Oct 26 22:17:04 pyapp ERROR django-q.cluster:655 connection already closed Oct 26 22:17:06 pyapp DEBUG django-q.cluster:350 queueing from DjangORM Oct 26 22:17:06 pyapp INFO django-q.cluster:407 Process-1:1 processing [xray-nevada-thirteen-mountain] Oct 26 22:17:08 pyapp INFO django-q.cluster:379 Processed [xray-nevada-thirteen-mountain] Oct 26 22:17:35 pyapp INFO django-q.tasks:74 Enqueued 87843 Oct 26 22:17:35 pyapp DEBUG django-q.tasks:75 Pushed ('hydrogen-minnesota-alanine-uniform', '61fc57aad473436f8d60d33cda08d3e6') Oct 26 22:17:35 pyapp INFO django-q.cluster:642 Process-1 created a task from schedule [4] Oct 26 22:17:35 pyapp ERROR django-q.cluster:655 connection already closed Oct 26 22:17:36 pyapp DEBUG django-q.cluster:350 queueing from DjangORM Oct 26 22:17:36 pyapp INFO django-q.cluster:407 Process-1:2 processing [hydrogen-minnesota-alanine-uniform] Oct 26 22:17:38 pyapp INFO django-q.cluster:379 Processed [hydrogen-minnesota-alanine-uniform] Oct 26 22:18:06 pyapp INFO django-q.tasks:74 Enqueued 87844 Oct 26 22:18:06 pyapp DEBUG django-q.tasks:75 Pushed ('two-pennsylvania-one-wyoming', 'a8b1619cfa5b414e8221beb9a11ad594') Oct 26 22:18:06 pyapp INFO django-q.cluster:642 Process-1 created a task from schedule [4] Oct 26 22:18:06 pyapp ERROR django-q.cluster:655 connection already closed

tawanda commented 3 years ago

Does that mean we can't use the CONN_MAX_AGE database setting with Django-q?

aaronn commented 2 years ago

Anyone have a good fix for this other than setting CONN_MAX_AGE to 0? It's causing a bunch of issues on our backend due to tasks failing mid-way.