Understanding Error Messages #6218
-
|
I have a Celery worker that processes messages from RabbitMQ. I'm guessing this is probably a Celery issue, but trying to see if there's any hint in Rabbit logs. I'm deploying Rabbit (3.11.1) on K8S using the Bitnami chart. What have been happening is: a consumer finishes to process a task, right after that, the next log message (in Celery) is a livenessProbe:
enabled: true
initialDelaySeconds: 120
timeoutSeconds: 20
periodSeconds: 30
failureThreshold: 6
successThreshold: 1
readinessProbe:
enabled: true
initialDelaySeconds: 10
timeoutSeconds: 20
periodSeconds: 30
failureThreshold: 3
successThreshold: 1The log shows the following block, but I confess I haven't been able to understand what exactly this is telling me. RabbitMQ LogsIs there any relevant information that could help be understand what's going on? |
Beta Was this translation helpful? Give feedback.
Answered by
lukebakken
Oct 21, 2022
Replies: 1 comment 5 replies
-
|
Please provide complete RabbitMQ logs before and after these events, as well as the timestamp of the following events:
|
Beta Was this translation helpful? Give feedback.
5 replies
-
|
These are the logs from Celery right before the issue (the time stamps on Rabbit are correct): Celery Logs{"message": "Task process-request[a67b7d84-2f4a-46cb-855e-0ead8369578e] succeeded in 53.903946735023055s: None", "data": {"id": "a67b7d84-2f4a-46cb-855e-0ead8369578e", "name": "process-request", "return_value": "None", "runtime": 53.903946735023055}, "@timestamp": "2022-10-21T16:34:44.070509", "level": "INFO", "logger": "celery.app.trace", "filename": "trace.py", "threadName": 140484845779856, "thread": 140484845779856, "created": 1666370084.0699437, "process": 1, "processName": "MainProcess", "relativeCreated": 180677885.53452492, "module": "trace", "funcName": "info", "levelno": 20, "msecs": 69.94366645812988, "pathname": "/usr/local/lib/python3.7/site-packages/celery/app/trace.py", "lineno": 131}
{"message": "consumer: Cannot connect to amqp://admin:**@myapp-rabbit:5672//: [Errno 110] Connection timed out.\nTrying again in 2.00 seconds... (1/100)\n", "@timestamp": "2022-10-21T16:36:27.711037", "level": "ERROR", "logger": "celery.worker.consumer.consumer", "filename": "consumer.py", "threadName": 140485066763728, "thread": 140485066763728, "created": 1666370187.7104967, "process": 1, "processName": "MainProcess", "relativeCreated": 180781526.0875225, "module": "consumer", "funcName": "_error_handler", "levelno": 40, "msecs": 710.4966640472412, "pathname": "/usr/local/lib/python3.7/site-packages/celery/worker/consumer/consumer.py", "lineno": 445}
{"message": "consumer: Cannot connect to amqp://admin:**@myapp-rabbit:5672//: [Errno 110] Connection timed out.\nTrying again in 4.00 seconds... (2/100)\n", "@timestamp": "2022-10-21T16:38:40.838786", "level": "ERROR", "logger": "celery.worker.consumer.consumer", "filename": "consumer.py", "threadName": 140485066763728, "thread": 140485066763728, "created": 1666370320.8385813, "process": 1, "processName": "MainProcess", "relativeCreated": 180914654.17218208, "module": "consumer", "funcName": "_error_handler", "levelno": 40, "msecs": 838.5813236236572, "pathname": "/usr/local/lib/python3.7/site-packages/celery/worker/consumer/consumer.py", "lineno": 445}
{"message": "consumer: Cannot connect to amqp://admin:**@myapp-rabbit:5672//: [Errno 110] Connection timed out.\nTrying again in 6.00 seconds... (3/100)\n", "@timestamp": "2022-10-21T16:40:56.000298", "level": "ERROR", "logger": "celery.worker.consumer.consumer", "filename": "consumer.py", "threadName": 140485066763728, "thread": 140485066763728, "created": 1666370456.0000997, "process": 1, "processName": "MainProcess", "relativeCreated": 181049815.69051743, "module": "consumer", "funcName": "_error_handler", "levelno": 40, "msecs": 0.09965896606445312, "pathname": "/usr/local/lib/python3.7/site-packages/celery/worker/consumer/consumer.py", "lineno": 445}
{"message": "consumer: Cannot connect to amqp://admin:**@myapp-rabbit:5672//: [Errno 110] Connection timed out.\nTrying again in 8.00 seconds... (4/100)\n", "@timestamp": "2022-10-21T16:43:13.216912", "level": "ERROR", "logger": "celery.worker.consumer.consumer", "filename": "consumer.py", "threadName": 140485066763728, "thread": 140485066763728, "created": 1666370593.2162504, "process": 1, "processName": "MainProcess", "relativeCreated": 181187031.84127808, "module": "consumer", "funcName": "_error_handler", "levelno": 40, "msecs": 216.25041961669922, "pathname": "/usr/local/lib/python3.7/site-packages/celery/worker/consumer/consumer.py", "lineno": 445}
{"message": "consumer: Cannot connect to amqp://admin:**@myapp-rabbit:5672//: [Errno 110] Connection timed out.\nTrying again in 10.00 seconds... (5/100)\n", "@timestamp": "2022-10-21T16:45:30.431945", "level": "ERROR", "logger": "celery.worker.consumer.consumer", "filename": "consumer.py", "threadName": 140485066763728, "thread": 140485066763728, "created": 1666370730.4312027, "process": 1, "processName": "MainProcess", "relativeCreated": 181324246.79350853, "module": "consumer", "funcName": "_error_handler", "levelno": 40, "msecs": 431.20265007019043, "pathname": "/usr/local/lib/python3.7/site-packages/celery/worker/consumer/consumer.py", "lineno": 445}
{"message": "Connected to amqp://admin:**@myapp-rabbit:5672//", "@timestamp": "2022-10-21T16:45:40.536081", "level": "INFO", "logger": "celery.worker.consumer.connection", "filename": "connection.py", "threadName": 140485066763728, "thread": 140485066763728, "created": 1666370740.5355577, "process": 1, "processName": "MainProcess", "relativeCreated": 181334351.14860535, "module": "connection", "funcName": "start", "levelno": 20, "msecs": 535.557746887207, "pathname": "/usr/local/lib/python3.7/site-packages/celery/worker/consumer/connection.py", "lineno": 22}
{"message": "mingle: searching for neighbors", "@timestamp": "2022-10-21T16:45:40.624569", "level": "INFO", "logger": "celery.worker.consumer.mingle", "filename": "mingle.py", "threadName": 140485066763728, "thread": 140485066763728, "created": 1666370740.6239207, "process": 1, "processName": "MainProcess", "relativeCreated": 181334439.51153755, "module": "mingle", "funcName": "sync", "levelno": 20, "msecs": 623.9206790924072, "pathname": "/usr/local/lib/python3.7/site-packages/celery/worker/consumer/mingle.py", "lineno": 40}
{"message": "mingle: sync with 1 nodes", "@timestamp": "2022-10-21T16:45:41.849989", "level": "INFO", "logger": "celery.worker.consumer.mingle", "filename": "mingle.py", "threadName": 140485066763728, "thread": 140485066763728, "created": 1666370741.8497102, "process": 1, "processName": "MainProcess", "relativeCreated": 181335665.30108452, "module": "mingle", "funcName": "sync", "levelno": 20, "msecs": 849.71022605896, "pathname": "/usr/local/lib/python3.7/site-packages/celery/worker/consumer/mingle.py", "lineno": 44}
{"message": "mingle: sync complete", "@timestamp": "2022-10-21T16:45:41.851624", "level": "INFO", "logger": "celery.worker.consumer.mingle", "filename": "mingle.py", "threadName": 140485066763728, "thread": 140485066763728, "created": 1666370741.851319, "process": 1, "processName": "MainProcess", "relativeCreated": 181335666.9099331, "module": "mingle", "funcName": "sync", "levelno": 20, "msecs": 851.3190746307373, "pathname": "/usr/local/lib/python3.7/site-packages/celery/worker/consumer/mingle.py", "lineno": 47}The logs in Rabbit before the block on the previous message only show the connections: Rabbit LogsA task finishes at 16h34. At 16h36m27s I get the first timeout from Celery, at this time I get a |
Beta Was this translation helpful? Give feedback.
-
|
Is this system overloaded or running on very low-spec VMs? |
Beta Was this translation helpful? Give feedback.
-
|
Yes, very low spec VMs. The traffic is extremely low, maybe processing somewhere between 5-10k msgs/day. The queue normally has somewhere between 10-15 messages (messages that will be retried) at any given time, no more than that. I still have ~20% of the cluster with free memory. Rabbit uses ~250MB, and it's at ~50% of the resource limit. |
Beta Was this translation helpful? Give feedback.
-
|
There was a sequence of exceptions in a channel, possibly related to
which is documented. We cannot tell if the channel belonged to that connection. My best guess is that the channel was just created on a connection that was shutting down. So this is mostly log noise. |
Beta Was this translation helpful? Give feedback.
-
|
Thanks for the help. I've been closely following the pods for the past few days. My impression is that this is mostly related to CPU usage. Despite the cluster being fairly low on memory (~25% free), and with lots of free CPU (~85% free), in certain times when multiple (not many really) messages hit (like 20-30) at the same time, there's a significant spike in CPU (from 100m to 300m), I had limits set to 300. The pod doesn't get killed because of the lack of resources, it seems that it just restricts the CPU usage, and then two things seem to happen: responses from liveness probe become extremely slow (like 40-60 seconds) and connections start to drop or can't be established and eventually the pod get's restarted. I'm saying eventually because there wasn't a direct relationship between liveness probes failing and restarts. There are multiple liveness probe warnings (like thousands) but not nearly as many restarts (like tens). Also saw an issue (can't find it right now) on Celery repo that was mentioning that more resources also helped with a similar issue. Thinking about the problem now, I can't think of much that can be done that could help troubleshoot this in the future. I'm guessing most Rabbit deployments (most definitely mission critical ones) have way more resources allocated, so this is probably a rare issue. Maybe checking resources could help to understand why are connections dropping/liveness probes extremely slow, but can't really think of an easy/simple/cheap way to implement that. About the logs, I honestly couldn't really understand what is saying, and haven't found much useful information on it that could help this specific case either, it seems that the resources issues happens before the actual termination, but there doesn't seem to be any hint that the the termination cause is resources limitation. I'm closing this, I'll update this if I discover anything else that can help people in the future. |
Beta Was this translation helpful? Give feedback.
Answer selected by
ccrvlh
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Please provide complete RabbitMQ logs before and after these events, as well as the timestamp of the following events:
connection timeout