Burst of DeadlineSoon exceptions

[gonvaled]

I get over 6700 exceptions in under a second, and then it works normally again. What exactly happens is as follows (please, see my implementation of BOSS and WORKER below): 1) The boss and the worker connects 2) I put a job in the tube 3) I receive it 4) Some time later, lots of DeadlineSoon exceptions arrive, very fast 5) After ca. 1s, they stop again, and a new job is received (which I never sent) 6) the situation is normal again, for a while, until we find ourselves again in step 4

My implementation is as follows:

class BeanstalkWorker:
    '''This class receives jobs from beanstalkd, encoded as JSON strings'''
    def __init__ (self, bt_tube, process_data, host = BEANSTALK_HOST, port = BEANSTALK_PORT):
        module_log.info("Connecting to beanstalk host %s, port %d, tube %s" % (host, port, bt_tube))
        self.json_support = JsonSupport()
        self.process_data = process_data
        try:
            self.beanstalk    = beanstalkc.Connection(host=host, port=port)
            self.beanstalk.watch(bt_tube)
        except beanstalkc.SocketError, e:
            module_log.warning("Problems connecting to beanstalk host %s, port %d: %s" % (host, port, e))
            self.beanstalk = None

    def show_stats(self):
        pprint(self.beanstalk.stats())

    def run(self):
        if not self.beanstalk:
            module_log.warning("We have no connection to the beanstalk host")
            return
        stop_requested = False
        while True:
            try:
                job = self.beanstalk.reserve(timeout=1)
            except beanstalkc.DeadlineSoon, e:
                module_log.info("DeadlineSoon: %s" % (e))
                job = None
            if not job:
                module_log.info("No job")
                if stop_requested : break
            else :
                module_log.info("Job found")
                data = self.json_support.Decode(job.body)
                if data:
                    if data.get('management', None) == 'STOP':
                        module_log.info("STOP requested")
                        stop_requested = True
                        job.delete()
                    else :
                        if self.process_data(data):
                            module_log.info("Job completed")
                            job.delete()

class BeanstalkBoss:
    '''This class sends dictionaries encoded as JSON strings to beanstalkd'''
    def __init__ (self, bt_tube, host = BEANSTALK_HOST, port = BEANSTALK_PORT):
        module_log.info("Connecting to beanstalk host %s, port %d, tube %s" % (host, port, bt_tube))
        try:
            self.beanstalk = beanstalkc.Connection(host=host, port=port)
            self.beanstalk.use(bt_tube)
        except beanstalkc.SocketError, e:
            module_log.warning("Problems connecting to beanstalk host %s, port %d: %s" % (host, port, e))
            self.beanstalk = None
        self.json_support = JsonSupport()

    def put(self, data):
        if not self.beanstalk:
            module_log.warning("We have no connection to the beanstalk host")
            return
        json = self.json_support.Encode(data)
        self.beanstalk.put(json)

This is the output:

2012-01-30 16:11:21,829 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:22,833 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:23,837 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:24,841 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:25,845 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:26,848 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:27,852 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:28,856 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:29,861 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:30,865 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:31,520 - beanstalk_support    - INFO       -       - DeadlineSoon: []
2012-01-30 16:11:31,520 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:31,521 - beanstalk_support    - INFO       -       - DeadlineSoon: []
2012-01-30 16:11:31,521 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:31,521 - beanstalk_support    - INFO       -       - DeadlineSoon: []
2012-01-30 16:11:31,521 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:31,521 - beanstalk_support    - INFO       -       - DeadlineSoon: []
2012-01-30 16:11:31,521 - beanstalk_support    - INFO       -       - No job
2012-01-30 16:11:31,521 - beanstalk_support    - INFO       -       - DeadlineSoon: []
2012-01-30 16:11:31,521 - beanstalk_support    - INFO       -       - No job
...

[gonvaled]

I have investigated the issue a bit, and it seems related to not returning "True" in the process_data function, which prevents the job from being deleted from the tube. The question remains if a burst of DeadlineSoon exception is to be expected in that situation.

[gonvaled]

Actually, the problem was that I was not deleting the job from the queue: I was receiving a job without data in the body (I do not know why) and my code was not handling properly that case. Now I also delete the jobs which have no data in the body.

The question is anyway still open: why so many DeadlineSoon exceptions, so fast?

[earl]

Yes, after a quick look at the code you don't delete a successfully reserved job if the job's body is empty.

So that means you have a job reserved, which you didn't delete, and then loop through to reserve(timeout=1) to wait for another job to reserve. As soon as the time-to-run of the first job (which you didn't delete) comes close to zero, beanstalkd will signal that by answering each reserve immediately with a DEADLINE_SOON reply. As you are not doing anything except outputting a log message in the DEADLINE_SOON case, you are basically busy-looping over reserve calls. In other words, you send reserves as fast as possible, beanstalkd answers with DEADLINE_SOON as fast as possible. And this will of course result in a lot of DeadlineSoon exceptions.

I hope that helps explaining what's going on.

[gonvaled]

Thanks earl, understood. The only open question that remains is: why am I getting jobs with empty body? I am the only one putting jobs in the tube, and they have definitely data.

[earl]

In the code snippet above, it's not really the body you are checking, but the result after JSON decoding. Maybe something's wrong in the JSON encoding/decoding.