Issue 1:
I have a host with a local-only (everything on the same host) Celery setup for some continuous data processing. Recently the load got much higher, all the CPU cores often are under 100% load and I've started to get WorkerLostError: Worker exited prematurely: exitcode 155 out of the blue multiple times per day. A worker works and then suddenly

ERROR/MainProcess] Task some_task[some_id] raised unexpected: WorkerLostError('Worker exited prematurely: exitcode 155.',)
Traceback (most recent call last):
File "...venv/local/lib/python2.7/site-packages/billiard/pool.py", line 1175, in mark_as_worker_lost
human_status(exitcode)),
WorkerLostError: Worker exited prematurely: exitcode 155.

I had Celery 3.1.19 but upgrading to the latest version changed nothing. Right now the versions are:

celery==3.1.20
amqp==1.4.9
billiard==3.3.0.22
kombu==3.0.33

I use Redis as the broker (tuned to save each message on the disk), and maybe these Celery settings will tell you something:

CELERY_ACKS_LATE = True
CELERYD_MAX_TASKS_PER_CHILD = 1
CELERYD_PREFETCH_MULTIPLIER = 1
#-Ofair
#CELERYD_CONCURRENCY is > 1
BROKER_CONNECTION_TIMEOUT = 4
BROKER_CONNECTION_MAX_RETRIES = 3
BROKER_TRANSPORT_OPTIONS = {
'fanout_prefix': True,
'fanout_patterns': True,
'visibility_timeout': CELERYD_TASK_TIME_LIMIT,
}

Issue 2:
Under high load we encountered duplicate job execution, as well as WorkerLostError: Worker exited prematurely: exitcode 155 exceptions.

We use --max-memory-per-child which leads to workers recycling (exit code 155) between jobs, and sometime the last job seems to be re-executed, as if the MainProcess didn't get the job result from the WorkerProcess.

Checklist

I have included the output of celery -A proj report in the issue.

(if you are not able to do this, then at least specify the Celery

version affected).

root@fe29479f29e2:/app# celery -A tasks report

software -> celery:4.2.0 (windowlicker) kombu:4.2.1 py:3.6.6
billiard:3.5.0.4 py-amqp:2.3.2
platform -> system:Linux arch:64bit imp:CPython
loader -> celery.loaders.app.AppLoader
settings -> transport:amqp results:db+postgres://postgres:**@db:5432/postgres

I have verified that the issue exists against the master branch of Celery.

Using current master HEAD 21baef5:

pip install 'git+https://github.com/celery/celery.git@21baef5#egg=celery [sqlalchemy]'

Steps to reproduce

Global scenario

with rabbitmq as broker, postgresql as backend using sqlalchemy

start celery with:

lot's of children worker processes to simulate high load: e.g. 64 workers

--max-tasks-per-child=1 to simulate workers process high churn

send lots of tasks

watch celery output for duplicate job execution:

[2018-10-17 09:46:15,694: INFO/MainProcess] Received task: work[fc23b1f5-a363-4c22-a1e3-28052811c237]

[2018-10-17 09:46:15,695: WARNING/ForkPoolWorker-5526] do_work:5570

[2018-10-17 09:46:12,491: ERROR/MainProcess] Task handler raised error: WorkerLostError('Worker exited prematurely: exitcode 155.',)
Traceback (most recent call last):
File "/usr/local/lib/python3.6/dist-packages/billiard/pool.py", line 1223, in mark_as_worker_lost
human_status(exitcode)),
billiard.exceptions.WorkerLostError: Worker exited prematurely: exitcode 155.

Scripted scenario

I made a reproducible scenario using docker and docker-compose:

https://gist.github.com/thomas-riccardi/6295ca2b39e16619141d349e7b189d75

# get scenario
git clone https://gist.github.com/6295ca2b39e16619141d349e7b189d75.git celery-duplicate-jobs
cd celery-duplicate-jobs

# start everything
docker-compose up --build; docker-compose down

# in a second terminal, in same directory: watch `celery` output
while sleep 1; do
echo ""
log=$(docker-compose logs worker)
echo "MainProcess receved task count uniqueness:"
echo "${log}" | grep "Received task:" | awk '{print $8}' | sort | uniq -c | sort -g | awk '{print $1}' | uniq -c
echo -n "WorkerLostError: "
echo "${log}" | grep "raised error: WorkerLostError" | wc -l
echo "Job execution uniqueness (job count per job execution count):"
echo "${log}" | grep do_work: | awk '{print $6}' | sort | uniq -c | sort -g | awk '{print $1}' | uniq -c
done

# to stop everything: just Ctrl-C on `docker-compose` and the bash script

Expected behavior

No (WorkerLostError) error logger.

Jobs are executed exactly once.

Scripted scenario

MainProcess received task count uniqueness:
1649 1
WorkerLostError: 0
Job execution uniqueness (job count per job execution count):
1534 1

The MainProcess received 1649 tasks, all unique.

The WorkerLostError exception is never logged.

There is no job that was executed multiple times.

Actual behavior

Many WorkerLostError exceptions are logged as error.

Some jobs are executed multiple times.

Scripted scenario

After some time (~1min on my machine) we start to get WorkerLostError exceptions and jobs executed multiple times:

MainProcess received task count uniqueness:
1649 1
WorkerLostError: 125
Job execution uniqueness (job count per job execution count):
1523 1
11 2

The MainProcess received 1649 tasks, all unique (so it's not a broker-level issue).

The WorkerLostError exception is logged 125 times.

There are 11 jobs that were executed 2 times.

More tests

No backend

When disabling the celery backend I could not reproduce the issues:

no WorkerLostError exception

no duplicated job execution

Redis backend

With redis as backend instead of postgresql, I quickly have a burst of WorkerLostError but it never increases afterward, and no duplicate job execution:

MainProcess receved task count uniqueness:
223 1
WorkerLostError: 0
Job execution uniqueness (job count per job execution count):
64 1

MainProcess receved task count uniqueness:
278 1
WorkerLostError: 10
Job execution uniqueness (job count per job execution count):
128 1

...

MainProcess receved task count uniqueness:
10000 1
WorkerLostError: 10
Job execution uniqueness (job count per job execution count):
10000 1

I believe the issue is also there, but the race condition isn't triggered somehow (is redis too fast?).

PostgreSQL backend, Redis broker

With redis as broker instead of rabbitmq (and still postgresql as backend) I could not reproduce the issues either:

no WorkerLostError exception

no duplicated job execution

Same conclusion as before.

More analysis

I tried to analyze the issue by adding lots of debug log in billiard/pool.py and celery/concurrency/asynpool.py.

What I understood happens:

...

MainProcess receives a job from the broker

MainProcess sends the job to one of its Worker

Worker receives the job

Worker puts ACK for the job in its out queue

Worker executes the job and finishes it

Worker puts the job result it in its out queue

Worker finds it must stop: (max memory, max task..): it exits with code 155

MainProcess sees its child Worker process die with code 155

MainProcess checks pending job passed to this Worker: seems to re-queue them on another Worker => duplicate job execution

MainProcess logs exception: 2018-10-12 14:08:35,781 celery.worker.request ERROR Task handler raised error: WorkerLostError('Worker exited prematurely: exitcode 155.',)

another Worker gets the job

...

What I understand should happen:

Different behavior starting at step 9.:

9. MainProcess should handle all remaining messages in Worker out queue: mark job as finished

10. MainProcess doesn't logs exception as there should be no job currently handled by the Worker

11. MainProcess acknowledges the job to the broker/backend

Debug logs

billiard.ResultHandler on_state_change

https://github.com/celery/billiard/blame/v3.5.0.4/billiard/pool.py#L812-L814

Logging here reveals that the MainProcess never processes the job response (state READY = 1), and most of the time not even the ACK (state ACK = 0). This explains why the job is re-executed by another worker.

(During my tests I saw the ACK always processed, but it was with a modified celery/billiard, see later hacks.)

Strange things in celery/billiard code/tried some fix/hacks

billiard.Pool._join_exited_workers, LOST_WORKER_TIMEOUT

In billiard there seems to be a feature to wait some time after the MainProcess sees a child Worker process die, to have some time to process the remaining messages from it.

It's controlled by LOST_WORKER_TIMEOUT.

billiard.Pool:

when a worker dies, we tag each of its jobs with current timestamp with on_job_process_lost

https://github.com/celery/billiard/blame/v3.5.0.4/billiard/pool.py#L1185-L1187

https://github.com/celery/billiard/blame/v3.5.0.4/billiard/pool.py#L1216-L1217

then later we check for such tagged jobs if timeout was reached, in which case we really fail these jobs (with mark_as_worker_lost)

https://github.com/celery/billiard/blame/v3.5.0.4/billiard/pool.py#L1131-L1140

Celery AsynPool child class:

it overrides on_job_process_lost to directly call mark_as_worker_lost:

https://github.com/celery/celery/blame/v4.2.1/celery/concurrency/asynpool.py#L1085-L1092

=> Celery AsynPool child class bypasses the whole LOST_WORKER_TIMEOUT timeout.

Code timeline

2013-05-01 billiard: code refactoring: notably adds on_job_worker_lost hook and mark_as_worker_lost: celery/billiard@06bc65e

2013-05-01 celery: adapt code for child class AsynPool: 43fda6f

by implementing the new on_job_worker_lost hook by directly calling mark_as_worker_lost, it bypasses the whole mechanism

2013-07-26 first WorkerLostError 155 bug report: celery/billiard#67

2013-11-28 second bug report: #1703

2013-11-28 wrong? fix: celery/billiard#87

Questions

Is it an issue that this feature was bypassed ?

Hack/Fix

Hack 1

I tried to restore the feature by removing the Celery AsynPool on_job_process_lost override: it doesn't fix the issue.

Hack 2

In fact there seem to be more breakage of this feature:

the timeout stored in job._lost_worker is reset each time _join_exited_workers is called, instead of being set only the first time we check this job when its worker is dead.

we also lose the exitcode when checking again a job

on_job_process_lost is called here: https://github.com/celery/billiard/blame/v3.5.0.4/billiard/pool.py#L1180-L1187

I'm not sure how to fix this, either call only once, or make on_job_process_lost idempotent?

Result: it did not fix the issue either... We just wait for 10 seconds now before calling mark_as_worker_lost: last out queue messages are still not processed.

billiard.Worker.__call__, _do_exit

Following the previous analysis, I checked the Worker exit code:

https://github.com/celery/billiard/blame/v3.5.0.4/billiard/pool.py#L274-L310

Questions

Why do we override sys.exit ?

How come we still end up in _do_exit since we seem to call sys.exit when workloop returns with EX_RECYCLE (the infamous 155).

Why do we do extra work for non win32 platform?

Why put DEATH (4) then sleep 1?

This comes from celery/billiard@896fc0d with no related issue

The MainProcess on_death then kills the worker with SIGTERM, this may risk breaking the explicit 155 recycle exit code mechanism...

This reveals there is clearly a race condition in the system, sleeping won't help

Why os._exit instead of sys.exit ?

os._exit doesn't seem to close/flush the fd/socket/Pipe, it may explain why the MainProcess misses messages.

sys.exit may risk closing resources still used by the MainProcess...

Hack/Fix

Hack 3

(Cumulative with hack 1 and 2)

Stopped to override sys.exit

Directly called exit

In _do_exit called sys.exit

Even tried explicit flush: self.outq._writer.close()

Result: still some WorkerLostError.

I also tried cumulatively to increase the sleep: with sleep(10) it seems to stop reproducing the issues, but it's still an ugly workaround...

Remaining questions

I don't have much more time to invest in this without help.

I did not dig into the whole "receiving and handling messages from workers" and how it interacts with the "worker is dead" management code.

Maybe we should try to guarantee working on the last messages from a worker when it dies, instead of just waiting 10s (that was even disabled/broken in 2013)

And/or maybe we should use a proper shutdown sequence, with a DEATH_ACK ? Something like:

Worker: send DEATH at exit, after having sent everything else. Wait for DEATH_ACK

MainProcess: receive DEATH, read order is guaranteed sequential (is it?): we are sure we already handled all application messages. Send DEATH_ACK

Worker: receive DEATH_ACK: sys.exit(exit_code)

MainProcess: wait for worker process death

maybe some retry? maybe some later force-kill?

Related issues

2013-07-26 celery/billiard#67

2013-11-28 #1703

2016-03-02 #3085