I have this strange problem with celery worker log (I have a stream handler setup to log INFO+ to the console).
I start celery with
celery --app=src.worker.app worker -P prefork -c 10
The problem happens when more than one jobs are running at the same time.
All of a sudden (I cannot pin-point the trigger to some specific set of actions by the worker tasks), I see that the logs go off format and linebreaks are missing and it appears that everything gets logged to a single line..
At this time, If I press enter on the celery worker window , there is no response (its like the terminal is not echoing anything back).
Notice Worker-7 and Worker-8 are working together , producing logs and all of a sudden linebreaks go missing (At: 2022-01-07 18:52:00,993: INFO/ForkPoolWorker-7)
[2022-01-07 18:51:55,728: WARNING/ForkPoolWorker-8] _HostBase: Missing transport info for testHost
[2022-01-07 18:51:55,729: INFO/ForkPoolWorker-8] Initialize Host testHost without transport
[2022-01-07 18:51:57,966: INFO/ForkPoolWorker-8] Collect Host OS details on 1191:tenant1_edge2:1
[2022-01-07 18:51:58,699: INFO/ForkPoolWorker-7] Collect Host OS details on 1190:tenant1_edge1:1
[2022-01-07 18:51:59,806: INFO/ForkPoolWorker-8] testHost - Initialize Ubuntu host
[2022-01-07 18:52:00,310: INFO/ForkPoolWorker-8] Initialize Host testHost without transport
[2022-01-07 18:52:00,490: INFO/ForkPoolWorker-7] testHost - Initialize Ubuntu host
[2022-01-07 18:52:00,993: INFO/ForkPoolWorker-7] Initialize Host testHost without transport
[2022-01-07 18:52:02,120: INFO/ForkPoolWorker-8] Collect Host OS details on 1191:tenant1_edge2:1
[2022-01-07 18:52:02,847: INFO/ForkPoolWorker-7] Collect Host OS details on 1190:tenant1_edge1:1
[2022-01-07 18:52:11,308: ERROR/ForkPoolWorker-8] utils::run_cmd: ERROR running cmd ssh -p 22 bhakta@192.168.31.110 -q -o StrictHostKeyChecking=no -o PasswordAuthentication=no -o UserKnownHostsFile=/dev/null "sudo timeout 120 rm -rf venv; python3.7 -m venv venv" -
[2022-01-07 18:52:11,309: ERROR/ForkPoolWorker-8] HostBase::_checkHostUsableForAT - Host testHost 1191:tenant1_edge2:1 Error python3.7 venv module is required for AT to function. Please install this module. cmd rm -rf venv; python3.7 -m venv venv produced code 1, out The virtual environment was not created successfully because ensurepip is not
available. On Debian/Ubuntu systems, you need to install the python3-venv
package using the following command.
I searched around and found similar issues (multiple processes writing to console: linebreaks) but not in the context of Celery.
Is there a Celery setting to prevent this issue?
Update: I narrowed this down and I created this piece of code that will reproduce the issue.
import threading
import logging
import time
import os
logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
streamFormatter = logging.Formatter(fmt='%(asctime)s %(levelname)-8s %(message)s', datefmt='%Y-%m-%d %H:%M:%S')
shdlr = logging.StreamHandler()
shdlr.setFormatter(streamFormatter)
shdlr.setLevel(logging.INFO)
logger.addHandler(shdlr)
def keepLoggingThead(i):
while True:
logger.info(f"Thread-{i}")
# The below requires password-less ssh to be setup..
# if I remove the -t then the logs are fine..
os.system("ssh -t 127.0.0.1 ls /tmp > /dev/null")
time.sleep(1)
tList = []
# The issue happens wnere there are more than 1 thread trying to do ssh with '-t' option..
for i in range(2):
t = threading.Thread(target=keepLoggingThead, args=(i,))
tList.append(t)
t.start()
for t in tList:
t.join()
produces this log:
➜ python thread_log.py
2022-01-10 20:24:28 INFO Thread-0
2022-01-10 20:24:28 INFO Thread-1
Connection to 127.0.0.1 closed.
Connection to 127.0.0.1 closed.
2022-01-10 20:24:31 INFO Thread-0
2022-01-10 20:24:31 INFO Thread-1
Connection to 127.0.0.1 closed.
Connection to 127.0.0.1 closed.
2022-01-10 20:24:34 INFO Thread-0
2022-01-10 20:24:34 INFO Thread-1
Connection to 127.0.0.1 closed.
Connection to 127.0.0.1 closed.
2022-01-10 20:24:36 INFO Thread-0
2022-01-10 20:24:36 INFO Thread-1
Connection to 127.0.0.1 closed.
Connection to 127.0.0.1 closed.
2022-01-10 20:24:39 INFO Thread-0
2022-01-10 20:24:39 INFO Thread-1
Connection to 127.0.0.1 closed.
Connection to 127.0.0.1 closed.
2022-01-10 20:24:42 INFO Thread-0
2022-01-10 20:24:42 INFO Thread-1
Connection to 127.0.0.1 closed.
Connection to 127.0.0.1 closed.
2022-01-10 20:24:44 INFO Thread-0
2022-01-10 20:24:44 INFO Thread-1
Connection to 127.0.0.1 closed.
Connection to 127.0.0.1 closed.
2022-01-10 20:24:47 INFO Thread-0
2022-01-10 20:24:47 INFO Thread-1
Connection to 127.0.0.1 closed.
Connection to 127.0.0.1 closed.
2022-01-10 20:24:50 INFO Thread-0
2022-01-10 20:24:50 INFO Thread-1
