Pulp3 high CPU utilization and unable to sync

bkwfanena · May 11, 2023, 2:42am

seeing this message in the system logs continuously

gunicorn[27472]: dest_loop.call_soon_threadsafe(_set_state, destination, source)
gunicorn[27472]: File “/opt/rh/rh-python38/root/usr/lib64/python3.8/asyncio/base_events.py”, line 764, in call_soon_threadsafe
gunicorn[27472]: self._check_closed()
gunicorn[27472]: File “/opt/rh/rh-python38/root/usr/lib64/python3.8/asyncio/base_events.py”, line 508, in _check_closed
gunicorn[27472]: raise RuntimeError(‘Event loop is closed’)
gunicorn[27472]: RuntimeError: Event loop is closed
gunicorn[27472]: [2023-05-11 12:16:44 +1000] [28669] [INFO] Booting worker with pid: 28669
gunicorn[27472]: pulp [None]: asyncio:ERROR: Task was destroyed but it is pending!
gunicorn[27472]: task: <Task pending name=‘Task-2’ coro=<_heartbeat() running at /usr/local/lib/pulp/lib64/python3.8/site-packages/pulpcore/content/init.py:45> wait_for=<Future pending cb=[_chain_future.._call_check_cancel() at /opt/rh/rh-python38/root/usr/lib64/python3.8/asyncio/futures.py:360, <TaskWakeupMethWrapper object at 0x7fa148ef15e0>()]>>
gunicorn[27472]: [2023-05-11 12:16:44 +1000] [28670] [INFO] Booting worker with pid: 28670

The task list is currently empty and there are no pending or running tasks

Versions of pulp

versions:

component: core
package: pulpcore
version: 3.22.4
component: rpm
package: pulp-rpm
version: 3.19.5
component: container
package: pulp-container
version: 2.14.5

bkwfanena · May 11, 2023, 9:46pm

Hi Team,
Can you please help us here. Looking at the logs, and tasks in the pulp DB, we dont see any tasks running or pending. we have also done a fresh install of pulp3 and we still get the same issue.
gunicorn workers are using high CPU and pulp-content and nginx cannot communicate

gerrod · May 15, 2023, 2:59pm

Is this the full stacktrace? Usually Pulp is installed to auto-restart when it encounters an error, but if there has been an error with the install/setup then this causes it to loop forever giving your high CPU utilization problem. Currently, from the excerpt you have provided it seems that it is the content-app that is continuously restarting, but there isn’t enough in the stacktrace to diagnose the issue.

bkwfanena · May 17, 2023, 11:45pm

Thanks for looking into it @gerrod
This is mostly the full stack trace and this keeps repeating itself

gunicorn: [2023-05-17 12:54:12 +0000] [1784] [INFO] Worker exiting (pid: 1784)
pulpcore-worker: pulp [None]: pulpcore.tasking.pulpcore_worker:INFO: Worker 1534@ip-10-39-128-23.ap-southeast-2.compute.internal was shut down.
pulpcore-worker: pulp [None]: pulpcore.tasking.pulpcore_worker:INFO: Worker 1507@ip-10-39-128-23.ap-southeast-2.compute.internal was shut down.
pulpcore-worker: pulp [None]: pulpcore.tasking.pulpcore_worker:INFO: Worker 1512@ip-10-39-128-23.ap-southeast-2.compute.internal was shut down.
pulpcore-worker: pulp [None]: pulpcore.tasking.pulpcore_worker:INFO: Worker 1577@ip-10-39-128-23.ap-southeast-2.compute.internal was shut down.
pulpcore-worker: pulp [None]: pulpcore.tasking.pulpcore_worker:INFO: Worker 1576@ip-10-39-128-23.ap-southeast-2.compute.internal was shut down.
pulpcore-worker: pulp [None]: pulpcore.tasking.pulpcore_worker:INFO: Worker 1585@ip-10-39-128-23.ap-southeast-2.compute.internal was shut down.
pulpcore-worker: pulp [None]: pulpcore.tasking.pulpcore_worker:INFO: Worker 1543@ip-10-39-128-23.ap-southeast-2.compute.internal was shut down.
pulpcore-worker: pulp [None]: pulpcore.tasking.pulpcore_worker:INFO: Worker 1525@ip-10-39-128-23.ap-southeast-2.compute.internal was shut down.
gunicorn: [2023-05-17 12:54:13 +0000] [1865] [INFO] Worker exiting (pid: 1865)
gunicorn: pulp [None]: asyncio:ERROR: Task was destroyed but it is pending!
gunicorn: task: <Task pending name='Task-2' coro=<_heartbeat() running at /usr/local/lib/pulp/lib64/python3.8/site-packages/pulpcore/content/__init__.py:60> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff2959d2280>()]>>
gunicorn: [2023-05-17 12:54:13 +0000] [1856] [INFO] Worker exiting (pid: 1856)
gunicorn: pulp [None]: asyncio:ERROR: Task was destroyed but it is pending!
gunicorn: task: <Task pending name='Task-2' coro=<_heartbeat() running at /usr/local/lib/pulp/lib64/python3.8/site-packages/pulpcore/content/__init__.py:60> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff295707940>()]>>
gunicorn: [2023-05-17 22:54:13 +1000] [1555] [INFO] Shutting down: Master
gunicorn: [2023-05-17 12:54:13 +0000] [1829] [INFO] Worker exiting (pid: 1829)
gunicorn: [2023-05-17 12:54:13 +0000] [1814] [INFO] Worker exiting (pid: 1814)
systemd: Stopped Pulp WSGI Server.
gunicorn: [2023-05-17 12:54:13 +0000] [1834] [INFO] Worker exiting (pid: 1834)
gunicorn: pulp [None]: asyncio:ERROR: Task was destroyed but it is pending!
gunicorn: task: <Task pending name='Task-2' coro=<_heartbeat() running at /usr/local/lib/pulp/lib64/python3.8/site-packages/pulpcore/content/__init__.py:60> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff29543a5e0>()]>>
gunicorn: pulp [None]: asyncio:ERROR: Task was destroyed but it is pending!
gunicorn: task: <Task pending name='Task-2' coro=<_heartbeat() running at /usr/local/lib/pulp/lib64/python3.8/site-packages/pulpcore/content/__init__.py:60> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff29570a250>()]>>
gunicorn: [2023-05-17 12:54:13 +0000] [1846] [INFO] Worker exiting (pid: 1846)
gunicorn: [2023-05-17 12:54:13 +0000] [1857] [INFO] Worker exiting (pid: 1857)
gunicorn: pulp [None]: asyncio:ERROR: Task was destroyed but it is pending!
gunicorn: task: <Task pending name='Task-2' coro=<_heartbeat() running at /usr/local/lib/pulp/lib64/python3.8/site-packages/pulpcore/content/__init__.py:60> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff29570d220>()]>>
systemd: Stopped Pulp Worker.
gunicorn: [2023-05-17 12:54:13 +0000] [1835] [INFO] Worker exiting (pid: 1835)
gunicorn: pulp [None]: concurrent.futures:ERROR: exception calling callback for <Future at 0x7ff28cb850d0 state=finished returned NoneType>
gunicorn: Traceback (most recent call last):
gunicorn: File "/opt/rh/rh-python38/root/usr/lib64/python3.8/concurrent/futures/_base.py", line 328, in _invoke_callbacks
gunicorn: callback(self)
gunicorn: File "/opt/rh/rh-python38/root/usr/lib64/python3.8/asyncio/futures.py", line 374, in _call_set_state
gunicorn: dest_loop.call_soon_threadsafe(_set_state, destination, source)
gunicorn: File "/opt/rh/rh-python38/root/usr/lib64/python3.8/asyncio/base_events.py", line 764, in call_soon_threadsafe
gunicorn: self._check_closed()
gunicorn: File "/opt/rh/rh-python38/root/usr/lib64/python3.8/asyncio/base_events.py", line 508, in _check_closed
gunicorn: raise RuntimeError('Event loop is closed')
gunicorn: RuntimeError: Event loop is closed
gunicorn: pulp [None]: asyncio:ERROR: Task was destroyed but it is pending!
gunicorn: task: <Task pending name='Task-2' coro=<_heartbeat() running at /usr/local/lib/pulp/lib64/python3.8/site-packages/pulpcore/content/__init__.py:60> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff2954388b0>()]>>
gunicorn: pulp [None]: asyncio:ERROR: Task was destroyed but it is pending!
gunicorn: task: <Task pending name='Task-2' coro=<_heartbeat() running at /usr/local/lib/pulp/lib64/python3.8/site-packages/pulpcore/content/__init__.py:60> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff2959d2250>()]>>
systemd: Stopped Pulp Worker.
systemd: Stopped Pulp Worker.
systemd: Stopped Pulp Worker.
gunicorn: pulp [None]: asyncio:ERROR: Task was destroyed but it is pending!
gunicorn: task: <Task pending name='Task-2' coro=<_heartbeat() running at /usr/local/lib/pulp/lib64/python3.8/site-packages/pulpcore/content/__init__.py:50> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /opt/rh/rh-python38/root/usr/lib64/python3.8/asyncio/futures.py:360, <TaskWakeupMethWrapper object at 0x7ff28cb852b0>()]>>
systemd: Stopped Pulp Worker.
gunicorn: [2023-05-17 22:54:14 +1000] [1520] [INFO] Shutting down: Master

we did manage to pinpoint the issue to urllib3 package from python. seems somewhere down the line, pulp installer download and install urllib3 version 2, and that causes this issue…
we have now pinned the version to be less than 2 and it seems to fix the problem

but we are not sure if version pinning will cause issues.

/usr/local/lib/pulp/bin/pip install urllib3==1.26.15