Rq: Job queued but not run

[fossilet]

I have a job not run, in the log of worker:

2016-11-15 23:18:34,617 11894 {q}default: [job details] (e47b96dc-d0f8-48b4-bbc9-090e6443080a)
2016-11-15 23:18:34,618 11894 Sent heartbeat to prevent worker timeout. Next one should arrive within 420 seconds.
2016-11-15 23:18:34,621 22069 Sent heartbeat to prevent worker timeout. Next one should arrive within 420 seconds.
2016-11-15 23:18:40,741 11894 Sent heartbeat to prevent worker timeout. Next one should arrive within 420 seconds.
2016-11-15 23:18:40,743 11894
2016-11-15 23:18:40,743 11894 * Listening on {q}high, {q}default...
2016-11-15 23:18:40,743 11894 Sent heartbeat to prevent worker timeout. Next one should arrive within 420 seconds.

22069 is the forked process to run the job. There should have been lines like below or error:

[timestamp] 22069 Sent heartbeat to prevent worker timeout. Next one should arrive within 420 seconds.
[timestamp] 22069 {q}high: Job OK (e47b96dc-d0f8-48b4-bbc9-090e6443080a)
[timestamp] 22069 Result is kept for 500 seconds

In redis, the job status is queued:

hgetall rq:job:e47b96dc-d0f8-48b4-bbc9-090e6443080a
1) "created_at"
2) "2016-11-15T15:18:34Z"
3) "status"
4) "queued"
...

This happens only occasionally.

[selwin]

Are you sure the queue and worker use the same Redis connection? I'm not aware of any bug in RQ that could lead to a worker not seeing jobs that are queued properly.

[nolanbrown]

I've been having the same issue. The redis connection is setup properly, I've inspected everything but sometimes queued jobs stay queued. They don't timeout or ever get processed by the worker.

[ssikiki]

+1 the same problem

My env: rq==0.8.0 redis==2.8.19

I've found that worker sometimes doesn't fetch job .
I'm sure the job has been sent to rq, because when I enqueued a job, I get the job status immediately, and it shows 'queued'.

taskid: 0b972f2e-48e7-4710-bb51-085a83978c56
queue: host.6JGQ2Y1
enqueued_at: 2017-06-02 09:14:55
status: queued

And I'm sure the worker wasn't dead, because when I sent another job to the same queue and same worker, it can be done.

below is the log, it shows the worker listen on two queues, one of them is host.6JGQ2Y1, , is alive from 6.1 20:02 to 6.2 11:21, but the job at 6.2 9:14 is missed

[2017-06-01 20:02:27] INFO [rq.worker:502] storage.ceph: consumer.storage.vol_act_v3()
[2017-06-01 20:02:27] INFO [rq.worker:99] storage.ceph: Job OK (6080387d-7779-4509-bd68-f18e917b4b7a)
[2017-06-01 20:02:27] INFO [rq.worker:108] Result is kept for 86400 seconds
[2017-06-01 20:02:27] INFO [rq.worker:489]
[2017-06-01 20:02:27] INFO [rq.worker:490] * Listening on host.6JGQ2Y1, storage.ceph...
[2017-06-02 11:21:15] INFO [rq.worker:502] host.6JGQ2Y1: consumer.vm.nic_act_v3()
[2017-06-02 11:21:15] INFO [rq.worker:99] host.6JGQ2Y1: Job OK (b2d694c2-d49e-4b41-8a2c-2d0a6288e452)
[2017-06-02 11:21:15] INFO [rq.worker:108] Result is kept for 86400 seconds
[2017-06-02 11:21:16] INFO [rq.worker:802] Cleaning registries for queue: host.6JGQ2Y1
[2017-06-02 11:21:16] INFO [rq.worker:802] Cleaning registries for queue: storage.ceph

This issue happens occasionally, so it's difficult to reproduce, could someone give me some tips how to debug the problem ? (from rq version 0.6.x to 0.8.0 , the issue has occurred)

[ssikiki]

I've found that when instantiate Worker class, set default_worker_ttl to 120 (default is 420) , The problem never happened again

[hitigon]

Having the same issue with latest rq + redis-cluster
@ssikiki
@nolanbrown
any chances you guys are using redis cluster as well?

[hitigon]

@ssikiki interesting! I'll give a try

[hitigon]

changing default_worker_ttl to 120 didn't work for me.

[fossilet]

@hitigon I remember rq does not have native redis cluster support. Regarding data loss with redis-cluster, there are several other issues maybe of help to you. The original problem is with redis.py.

[hitigon]

@fossilet yeah, I am trying to make rq work with Redis Cluster. I am using redis-py-cluster which is based on redis.py. There might be some data loss happening as I saw rpush/lpush a job id to the queue didn't happen sometimes. This also may be related to the implementation of pipeline in redis-py-cluster

[fossilet]

@hitigon I had some try and tweaks with it at https://github.com/rq-cluster, but I still have quiet job loss occasionally. Then I reverted back, and found out even rq with redis.py loses job occasionally, i.e. this issue.

[hitigon]

@fossilet any ticket you can point to that is related to job loss on rq and redis.py? Also, have you tried the latest redis-py-cluster (1.3.X) ?

[fossilet]

@hitigon yes, this issue. I have not tried the new versions. Good luck!

[hitigon]

@fossilet which one?

[jjjjw]

I have seen this as well using RQ 0.8.0 and python redis 2.10.5. I am not using redis-py-cluster.

The issue I saw is the same as others reported. I can see jobs in Redis that were never added to the queues, or silently failed in some other way. I don't know how to reproduce, it only happens occasionally.

My current workaround is to poll Redis for zombie jobs and requeue them.

[kvnramirez]

There is any solution for this problem?

[lifenautjoe]

Same issue here.

Once in a while we get complaints that somethings not working on the application, 9/10 times its rq workers doing nothing while having thousands of jobs queued.

[James-Quigley]

@jjjjw mind sharing what your zombie job requeueing logic looks like?

[zsblevins]

Also seeing this issue. I have several applications that use RQ and I've only noticed it in a single application.

The job gets created and persisted in Redis, but the queue doesn't have any reference to the job and it never gets run. Here's some sample behavior:

>>> from redis import Redis
>>> rconn = Redis(host="<redacted>", db=5)
>>> from rq.job import Job
>>> job = Job.fetch('f5514216-61cb-4967-a7dc-0a02a43216da', connection=rconn)
>>> job.id
'f5514216-61cb-4967-a7dc-0a02a43216da'
>>> job.get_status()
'queued'
>>> job.origin
'render_v1'
>>> job.requeue() # This shows it's not on the failed job registry and thus can't be requeued
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/apps/python3.6/lib/python3.6/site-packages/rq/job.py", line 529, in requeue
    self.failed_job_registry.requeue(self)
  File "/apps/python3.6/lib/python3.6/site-packages/rq/registry.py", line 194, in requeue
    raise InvalidJobOperation
rq.exceptions.InvalidJobOperation
>>> job.to_dict()
{'created_at': '2019-09-27T21:27:24.600974Z', 'data': b"x\x9c%NK\x0e\x820\x14\xd4\xc4D\xd4\xa5Wp\x81\x0b\x9aBK\x913\xb83\xee\t\x96g@C1\xf4a\xdc\x98x\x80\xee|^\xc1s\xda\xc8\xac\xe6\x93\xcc\xcck\xf6\xf9NF\x84n\x0e\x0f\xd0\x03\x02\xb9\xb5\x05D\xe8\x19\x96\xf6jY\x0f\xa6\x82\x9e\xdc\xf2\xf0'Go\xd2\x9b\xb6O\n]\x00w0X4\x15\xb9\x8dNr)d\x9aE\xb1\x10I$\x13\xa5\xa2\x1d\xf72\xcfN \xa5\x12YuN\xc9-\x1a_\\b\xd3\x19\xdaO]Pw\x16M\xd9\xfa\xcd\x15X\x1e3{\xd1\x9c+\xaf\xac\xae\xa1-\x8b1\x9b\xdd\xc0\x1f\x18\x90\xd8\x0f\x85X<\xae", 'origin': 'render_v1', 'description': "execute(event_id='c2943457-1332-4266-8057-97be44637df5', hostname='<redacted>', iteration=1, schema_name='peer')", 'enqueued_at': '2019-09-27T21:27:24.601033Z', 'timeout': 180, 'failure_ttl': 604800, 'status': 'queued'}
>>> from rq import Queue
>>> queue = Queue('render_v1', connection=rconn)
>>> queue.jobs
[]
>>> queue.fetch_job(job.id)
Job('f5514216-61cb-4967-a7dc-0a02a43216da', enqueued_at=datetime.datetime(2019, 9, 27, 21, 27, 24, 601033))
>>> queue.jobs
[]
>>> queue.failed_job_registry.get_job_ids()
[]

[orionw]

Currently seeing the same issue. Any solutions?

[hasslercastro]

Currently seeing the same issue. Any solutions?

Same here

[mrinalsinha]

Hello, I'm also facing the same issue, my tasks remain in the queue even when the workers are free. Can anyone please suggest if not this then, what is better to switch to.

[hasslercastro]

I was using a docker container and for some reason the workers never took a job out from the queue
I found this in other thread, basically create workers from code using multiprocessing

r = redis.Redis(host='redis', port=6379)
q = Queue(connection=r)

#Debug, cleaning old jobs
q.empty()


def need_burst_workers():
    # check database or redis key to determine whether burst worker army is required
    return True #boolean

def num_burst_workers_needed():
    # check the number, maybe divide the number of pending tasks by n
    return 2 #integer


def runworker():
    #Burst mode kills the worker once it has completed its jobs
    qs=["default"]
    with Connection(r):
        if need_burst_workers():
            for i in range(num_burst_workers_needed()):
                multiprocessing.Process(target=Worker(qs).work, kwargs={'burst': False}).start()
        else:
            time.sleep(10) #in seconds

#Workers will read enqueued jobs
runworker()

[siddharthshah3030]

I found a workaround untill problem is fixed
if a job is stuck at "queued", i delete and enqueue again

from rq import Queue
from redis import Redis
redis_conn = Redis()
q = Queue(connection=redis_conn)

job = q.fetch_job('my_id') # Returns job having ID "my_id"
job.get_status() # -> 'queued'

job.delete() # -> deletes the job 

job.get_status() # -> "" job does not exist

# now enqueue job again normally and it works and runs successfully

[atainter]

For what it's worth, my team is having the same problem. It's making RQ unusable for us. Seems like this is a bug.

[selwin]

@atainter are you able to nail down whether the job was actually ever in the queue (pushed to Redis list)?

I’m just curious because a number of people are reporting this bug, but none are able to reproduce this. Perhaps it’s a temporarily blip with the worker box or something similar?

[atainter]

Yes, looks like the job is in Redis and stuck in a "queued" status. I'm not able to reproduce with a certain job - it randomly happens, but it's somewhat frequent. I looked for zombie workers, but everything seemed normal.

[selwin]

In that case, let me work on a patch that increases debug logging around this area so we can try to nail down what happens the next time this happens again.

On Jan 28, 2021, at 8:27 AM, Aaron Tainter [e-mail] wrote:


Yes, looks like the job is in in Redis and stuck in a "queued" status. I'm not able to reproduce with a certain job - it randomly happens, but it's somewhat frequent. I looked for zombie workers, but everything seemed normal.

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub, or unsubscribe.

[atainter]

Hey @selwin any update on this?

[atainter]

After some more digging, my theory is that the job is added to Redis as rq:job:ID, but not added to 'rq.default'. This would explain why queue.jobs does not fetch the job, but job_class.fetch(id) does. One reads from the 'rq:job' key while the other gets ids from 'rq:default' and uses them to fetch data from 'rq:job'.

I'm going to continue to try to look into this. Maybe there's a silent redis connection error when RQ enqueues the job in the 'rq:default' key?

[atainter]

Under further investigation, it looks like enqueue uses a pipeline to update redis. I wonder if one if the commands is silently failing: https://stackoverflow.com/a/54153873

[selwin]

@atainter sorry I've been super busy this week.

Under further investigation, it looks like enqueue uses a pipeline to update redis. I wonder if one if the commands is silently failing

I don't think this is the problem. My first guess would be the job is dropped after the job is popped of the queue (Redis list), but before the job is put on the StartedJobRegistry (sorted set).

My intention is to add logging.debug() calls around this area during the enqueue process:

1. Job is successfully added to queue (Redis list)

And on the worker process, add logging.debug() here:

1. Prior/after job is popped of the queue
2. Prior/after job is added to StartedJobRegistry

I think the job became orphaned between steps 1 & 2.

Having said that, I've never had these kind of issues though, could it be that the hardware you're running RQ on is overutilized?

[atainter]

I don't think it's underutilized, but I could be wrong. We're in Kubernetes and running 1000m (reqs) to 1500m (limit). Our Redis instance is hosted in AWS. Not sure if there could be some cross domain issue there, but it works in other environments. I'll look into this with some monitoring tools.

I added some code in a subclass to log prior/after job is popped off the queue. Let me see if I can gather any data from that and I'll look into the StartedJobRegistry in parallel.

[atainter]

Okay, so I was able to reproduce with some logging. It looks like jobs that get stuck in this queued state call 'rpush' to add the job to the Redis queue, but they don't get popped off the queue in the worker. i.e. this code doesn't get called for stuck jobs, but it does for other jobs:

class QueueWithLogging(Queue):
    @classmethod
    def lpop(cls, queue_keys, timeout, connection=None):
        result = RQQueue.lpop(queue_keys, timeout, connection=connection)

        if result is not None:
            queue_key, job_id = map(as_text, result)
            queue_logger.info(f"Popping job_id from the queue: {queue_key} {job_id}")

        return result

[selwin]

But were you able to verify that the job successfully get pushed into the list?

One way to find out about this:

1. Stop your workers
2. Put a logging call after rpush and confirm that the job ID is indeed in the list after the job is enqueued

Repeat this for a few hundred/thousand jobs and see if any of them actually don't get pushed to the list.

[atainter]

I just did a bunch of testing for this and I think I found something. Originally I had 6 workers and this was happening quite often. I scaled back to 1 worker and I had a really difficult time reproducing this, so I ramped back up to 2. To figure out what was going on, I logged the current state of the job_id queue in the service after all jobs in a batch had been scheduled AND in a worker before it calls the blpop method.

Here's a spreadsheet of the logs from my machines:
https://docs.google.com/spreadsheets/d/1dbh1NokDO-pjkwnzDjRzWU1kuhS9EgnMgrbwSeCUY3s/edit?usp=sharing

Some things to note:

1. Logs are in reverse chronological order with oldest logs at the bottom
2. I noticed this batch has some duplicate jobs due to a bug in our code. I don't think this would matter, but I'm not sure
3. The lost job ID is bolded in red

Looks like the workers blpop jobs off the queue right as the queue writes to it using an rpush. Workers 1 and 2 pop
ffd2d819-43d7-4c60-8654-c23af2fe4ab3 and b177150f-4f53-442a-a734-f053c3dab1b8 off the queue right as 4fd996cd-a4f6-4a09-a4ce-0b877acff2d9 is pushed into the queue. If you follow the logs, you'll see that 4fd996cd-a4f6-4a09-a4ce-0b877acff2d9 is never popped and is not in the job queue when the service logs the ids.

This leads me to believe that there is a race condition that happens between blpop and rpush. Is there a way to verify this? Can lock the table to prevent this from happening? I'm not a Redis expert.

[atainter]

The other interesting thing I found is that RedisPy swallows a ConnectionError for a pipeline.execute call: https://github.com/andymccurdy/redis-py/blob/master/redis/client.py#L4156-L4169

Looks like BusyLoadingError also extend ConnectionError: https://github.com/andymccurdy/redis-py/blob/master/redis/exceptions.py#L20

I'm not sure what BusyLoadingError or ConnectionError is, but I wonder if this could also be silently failing because the blpop is popping the queue during the rpush and the key is "busy".

EDIT: I don't think this is the issue. I added some logging and reproduced, but did not see the error. I'm thinking it's the write race described above.

[atainter]

@selwin I was able prevent data loss by suspending the workers before adding jobs to the queue and resuming them after. It seems like this only happens if I send more jobs at one time than there are workers. I think the race condition happens when the last job_id is popped off the queue and a job is added at the same time.

Here's my pseudo code:

    try:
        suspend(redis_conn)

        # Hack to break workers out of blpop
        workers = Worker.all(redis_conn)
        for _ in workers:
            job_queue.enqueue(noop_job, result_ttl=60)

        for txn in txns:
            job_queue.enqueue(job_func, txn.data, job_id=txn.id)

    finally:
        resume(redis_conn)

This doesn't seem like a long term fix, though. Jobs could be added from several services and there could be a race condition that resumes the workers in one server right after they're suspended in another. Additionally, there are a bunch of noop jobs that are unnecessarily added.

Perhaps you could switch to this pattern instead? https://redis.io/commands/rpoplpush#pattern-reliable-queue

[selwin]

This leads me to believe that there is a race condition that happens between blpop and rpush. Is there a way to verify this? Can lock the table to prevent this from happening? I'm not a Redis expert.

Redis is single threaded by design so race conditions can't happen within Redis itself, only within our code.

I think the race condition happens when the last job_id is popped off the queue and a job is added at the same time.

So this can't actually happen.

Reading your logs, it seems like job 4fd996cd-a4f6-4a09-a4ce-0b877acff2d9 was never pushed into the queue. If this is the case, using rpoplpush won't help, since it was never in the queue (list) to begin with. And this command works doesn't work for multiple keys.

So I think what happens is when rpush is called, Redis is busy so it silently drops it. What I'll do is see whether we can check the result of pipeline.execute() to see whether we can detect this. Do you mind logging the result of pipeline.execute() here https://github.com/rq/rq/blob/master/rq/queue.py#L481 ?

Sorry for the hassle but I can't reproduce this on my setup.

[atainter]

@selwin I made a change to add additional logging and merged into the env where we were seeing this issue. However, right before merging the change, we decided to update our Redis cluster from 5.0.4 to 5.0.6 release notes.

I disabled my temporary workaround and haven't been able to reproduce 🤞 . I'll continue monitoring with my logging changes for the next couple days and I'll let you know if anything changes. Thanks for the help!

[hossein761]

I removed celery from my project to use a "simpler" tool, but having the same issue. my Redis version 5.0.10. Using django, I see the jobs in the default queue with the status: scheduled they are stuck in there.

[jtfidje]

Related to this, we now experience an issue where a job gets stuck in the deferred state. occasionally when a job depends on another, it won't get queued when the first job finishes. I can't reproduce it by "will", but if I queue the same set of jobs enough times it always happens eventually.

Edit:
I'd like to add that we've just made some performance improvements which has resulted in a much heavier load on Redis. We did not observe this behavior even once before, but now after the heavy Redis load it happened almost immediately when running our tests.

This may be completely random and just a coincidence, but maybe it's got something to do with it? :)

Edit:
Checking the registers, my job is never deleted from the DeferredJobRegistry, and never added to another registry.

Edit:
Sorry for all the edits here. Currently debuging and finding small clues. I can see that when this issue happens, the dependent_job_ids ( https://github.com/rq/rq/blob/master/rq/queue.py#L507 ) is just an empty list when it really shouldn't be ( and it is not in 9/10 cases )

Edit:
Last edit for today, promise!

So I did this in Queues.enqueue_dependents ( https://github.com/rq/rq/blob/master/rq/queue.py#L507 ):

dependent_job_ids = [
    as_text(_id) for _id in pipe.smembers(dependents_key)
]
if dependent_job_ids == []:
    import time
    from loguru import logger

    time.sleep(1)
    test = [as_text(_id) for _id in pipe.smembers(dependents_key)]
    if test:
        logger.error(f"dependent_job_ids: {dependent_job_ids}")
        logger.error(f"dependent_job_ids after sleep(1): {test}")

My two error logs actually triggers and my error is now gone. Unfortunately, I have no idea how to move on from here. Hope any of you are able to help investigate further :) Please let me know if there is anything else I can do to help here!

[jtfidje]

I also experience now issues where if I enqueue jobs too quickly in succession, I.e. Job1 --> Job2. Job2 depends on Job1, then the dependent job ( Job2 in this case ) is forever stuck in deferred like above. Adding all my jobs to a list and calling enqueue in a for-loop followed by a time.sleep fixes this, but this is not a good solution. Quite often I have to enqueue a lot of jobs at once ( whenever my API receives an event ) and therefore sleeping is quite a performance hit.

Edit:
It seems like setting job.origin and then calling job.save() on each job before enqueuing them in a loop also works.

[LorenRd]

Just opened this issue https://github.com/rq/rq/issues/1433 Can someone help?

[zsblevins]

An additional bit of context to add. We hit this bug again in another application when we switched from the default Worker to SimpleWorker (to workaround issues with GRPC streaming being incompatible with forking). It occurs VERY frequently with the move to SimpleWorker.

We upgraded our redis cluster to 5.0.6 and that did not resolve the issue.

[abhisuri97]

I came across this issue as well. Killing the worker thread and restarting seems to "fix" it, but I'd rather not have to resort to that in production. Does anyone have any idea what to do here?

[essadek]

I'm having the same issue, I noticed that when jobs are chained one after one immediately the jobs are not executed, however if there is some interval in between the jobs get executed.
Update:
Now that I increased the number of workers to 5, chained jobs are executed with success.

[daverin]

same findings as @abhisuri97 in production. I've spotted it a few times locally in my docker compose environment, but thus far I haven't been able to consistently reproduce the issue.

[dpereira]

This report looks eerily familiar:

https://github.com/redis/redis/issues/7128

We had this issue in production, and went through the following changes:

• Removed rq in favor of an in-house client lib for queueing/dequeing messages.
• Changed redis client implementation

• Finally, replaced redis and the whole implementation with one based in Active MQ.

  We only stopped seeing behaviors like the ones in this thread after we stopped using redis for queue/jobs entirely.

[selwin]

So it’s a Redis issue? If it is, then unfortunately there’s nothing that we can do.

On May 6, 2021, at 11:03 AM, Diego Pereira @.*> wrote:


This report looks eerily familiar:

redis/redis#7128

We had this issue in production, and went through the following changes:

Removed rq in favor of an in-house client lib for queueing/dequeing messages.
Changed redis client implementation
Finally, replaced redis and the whole implementation with one based in Active MQ.
We only stopped seeing behaviors like the ones in this thread after we stopped using redis for queue/jobs entirely.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or unsubscribe.

[dpereira]

I can't say 100% it was redis. Can't say it isn't.

It could be a bug related to incorrect redis usage in rq that we carried in our implementation as well, for example. Just wanted to share our experience, in the hope this helps with the troubleshooting.