title: Celery : Task not execute from queue after the first few times
body: <p><b>[Prerequisite]</b></p>
  
  <ul>
  <li>Django==1.5.8</li>
  <li>celery==3.0.23</li>
  <li>django-celery==3.0.23</li>
  <li>amqp==1.4.6</li>
  </ul>
  
  <p><b>[Steps]</b></p>
  
  <ul>
  <li>django <i>views.py</i> send message via <i>RabbitMQ</i> to <i>celery task queue</i></li>
  <li><i>Celery</i> read messages from queue and execute tasks in order</li>
  <li>Each task wouldn't take long time</li>
  </ul>
  
  <p><b>[Problem]</b></p>
  
  <ul>
  <li>For the first few times, celery successfully executed tasks but number of tasks is not reduced from the queue (Task is constantly stacked up at the queue)</li>
  <li>Finally, celery is not executing task from queue after the first few times</li>
  </ul>
  
  <p><b>[Hint]</b></p>
  
  <ul>
  <li>I thought that following could be hints to solve problem</li>
  <li>For the first few times, task is executed well but it is not removed from the queue</li>
  <li><code>Task utils.tasks.do_things_1[027918df-a6ef-4712-a8c8-5b380d5bd0f6] succeeded in 1415464878.25s: None</code> => Why does it take so long?</li>
  </ul>
  
  <p><b>[Detail description with log]</b></p>
  
  <ul>
  <li><i>Check number of tasks and worker</i></li>
  </ul>
  
  <blockquote>
    <p>$ sudo rabbitmqctl list_queues name messages consumers | grep celery</p>
    
    <blockquote>
      <p><strong>celery 0   0</strong>       (0 tasks, 0 worker)</p>
    </blockquote>
  </blockquote>
  
  <ul>
  <li><i>Celery Information when starts with Debug mode</i></li>
  </ul>
  
  <blockquote>
    <p>$ ./manage.py celery worker --loglevel=debug</p>
    
    <blockquote>
      <p>celery@75e28d96-1a33-4e08-8283-a31813a4124d v3.0.23 (Chiastic Slide)</p>
      
      <p>Linux-3.2.0-34-generic-pae-i686-with-Ubuntu-14.04-trusty</p>
      
      <p>[config]</p>
      
      <blockquote>
        <p>broker:      amqp://guest@localhost:5672//</p>
        
        <p>app:         default:0xb6b2188c (djcelery.loaders.DjangoLoader)</p>
        
        <p>concurrency: 1 (processes)</p>
        
        <p>events:      OFF (enable -E to monitor this worker)</p>
      </blockquote>
      
      <p>[queues]</p>
      
      <blockquote>
        <p>celery:      exchange:celery(direct) binding:celery</p>
      </blockquote>
      
      <p>[Tasks]</p>
      
      <blockquote>
        <p>utils.tasks.<strong>do_things_1</strong></p>
        
        <p>utils.tasks.<strong>do_things_2</strong></p>
        
        <p>utils.tasks.<strong>do_things_3</strong></p>
      </blockquote>
      
      <p>[2014-11-16 14:09:13,769: DEBUG/MainProcess] [Worker] Loading modules.</p>
      
      <p>[2014-11-16 14:09:13,771: DEBUG/MainProcess] [Worker] Claiming components.</p>
      
      <p>[2014-11-16 14:09:13,771: DEBUG/MainProcess] [Worker] Building boot step graph.</p>
      
      <p>[2014-11-16 14:09:13,772: DEBUG/MainProcess] [Worker] New boot order: {ev, queues, beat, pool, 
      mediator, autoreloader, timers, state-db, autoscaler, consumer}</p>
      
      <p>[2014-11-16 14:09:13,774: DEBUG/MainProcess] Starting celery.worker.hub.Hub...</p>
      
      <p>[2014-11-16 14:09:13,774: DEBUG/MainProcess] celery.worker.hub.Hub OK!</p>
      
      <p>[2014-11-16 14:09:13,774: DEBUG/MainProcess] Starting celery.concurrency.processes.TaskPool...</p>
      
      <p>[2014-11-16 14:09:13,782: DEBUG/MainProcess] celery.concurrency.processes.TaskPool OK!</p>
      
      <p>[2014-11-16 14:09:13,787: DEBUG/MainProcess] Starting celery.worker.mediator.Mediator...</p>
      
      <p>[2014-11-16 14:09:13,788: DEBUG/MainProcess] celery.worker.mediator.Mediator OK!</p>
      
      <p>[2014-11-16 14:09:13,788: DEBUG/MainProcess] Starting celery.worker.consumer.Consumer...</p>
      
      <p>[2014-11-16 14:09:13,789: WARNING/MainProcess] celery@75e28d96-1a33-4e08-8283-a31813a4124d ready.</p>
      
      <p>[2014-11-16 14:09:13,789: DEBUG/MainProcess] consumer: Re-establishing connection to the broker...</p>
      
      <p>[2014-11-16 14:09:13,800: DEBUG/MainProcess] Start from server, version: 0.9, properties: {u'information': u'Licensed under the MPL.  See <a href="http://www.rabbitmq.com/" rel="nofollow">http://www.rabbitmq.com/</a>', u'product': u'RabbitMQ', u'copyright': u'Copyright (C) 2007-2013 GoPivotal, Inc.', u'capabilities': {u'exchange_exchange_bindings': True, u'connection.blocked': True, u'authentication_failure_close': True, u'basic.nack': True, u'consumer_priorities': True, u'consumer_cancel_notify': True, u'publisher_confirms': True}, u'platform': u'Erlang/OTP', u'version': u'3.2.4'}, mechanisms: [u'PLAIN', u'AMQPLAIN'], locales: [u'en_US']</p>
      
      <p>[2014-11-16 14:09:13,801: DEBUG/MainProcess] Open OK!</p>
      
      <p>[2014-11-16 14:09:13,801: INFO/MainProcess] consumer: Connected to amqp://guest@127.0.0.1:5672//.</p>
      
      <p>[2014-11-16 14:09:13,802: DEBUG/MainProcess] using channel_id: 1</p>
      
      <p>[2014-11-16 14:09:13,803: DEBUG/MainProcess] Channel open</p>
      
      <p>[2014-11-16 14:09:13,804: DEBUG/MainProcess] consumer: basic.qos: prefetch_count->4</p>
      
      <p>[2014-11-16 14:09:13,805: DEBUG/MainProcess] using channel_id: 2</p>
      
      <p>[2014-11-16 14:09:13,805: DEBUG/MainProcess] Channel open</p>
      
      <p>[2014-11-16 14:09:13,812: DEBUG/MainProcess] consumer: Ready to accept tasks!</p>
    </blockquote>
  </blockquote>
  
  <ul>
  <li><i>Check number of tasks and worker</i></li>
  </ul>
  
  <blockquote>
    <p>$ sudo rabbitmqctl list_queues name messages consumers | grep celery</p>
    
    <blockquote>
      <p><strong>celery 0   1</strong>       (0 tasks, 1 worker)</p>
    </blockquote>
  </blockquote>
  
  <ul>
  <li><i>Some event occured in views.py and send message to execute <strong>do_things_1, do_things_2, do_things_3</strong>(1st attempts)</i></li>
  </ul>
  
  <blockquote>
    <blockquote>
      <p>[2014-11-16 14:53:51,874: INFO/MainProcess] Got task from broker: utils.tasks.<strong>do_things_1</strong>[027918df-a6ef-4712-a8c8-5b380d5bd0f6] eta:[2014-11-16 14:53:52.835084+09:00]</p>
      
      <p>[2014-11-16 14:53:51,875: INFO/MainProcess] Got task from broker: utils.tasks.<strong>do_things_2</strong>[a1c09645-32fb-4399-802b-60ca826fa6bc] eta:[2014-11-16 14:53:52.851516+09:00]</p>
      
      <p>[2014-11-16 14:53:51,880: INFO/MainProcess] Got task from broker: utils.tasks.<strong>do_things_3</strong>[5a66f885-baf2-49ab-b82f-733d2b68fe7b] eta:[2014-11-16 14:53:52.852527+09:00]</p>
      
      <p>[2014-11-16 14:53:51,880: DEBUG/MainProcess] consumer: basic.qos: <strong>prefetch_count->7</strong></p>
      
      <p>[2014-11-16 14:53:52,882: DEBUG/MainProcess] consumer: basic.qos: <strong>prefetch_count->4</strong></p>
      
      <p>[2014-11-16 14:53:52,917: DEBUG/MainProcess] Mediator: Running callback for task: utils.tasks.<strong>do_things_1</strong>[027918df-a6ef-4712-a8c8-5b380d5bd0f6]</p>
      
      <p>[2014-11-16 14:53:52,918: DEBUG/MainProcess] TaskPool: Apply  (args:('utils.tasks.<strong>do_things_1</strong>', '027918df-a6ef-4712-a8c8-5b380d5bd0f6', [u'0301010101', u'1'], {}, {'utc': True, 'is_eager': False, 'chord': None, 'group': None, 'args': [u'0301010101', u'1'], 'retries': 0, 'delivery_info': {'priority': None, 'routing_key': u'celery', 'exchange': u'celery'}, 'expires': None, 'task': 'utils.tasks.do_things_1', 'callbacks': None, 'errbacks': None, 'hostname': '************************', 'taskset': None, 'kwargs': {}, 'eta': '2014-11-16T05:53:52.835084', 'id': '027918df-a6ef-4712-a8c8-5b380d5bd0f6'}) kwargs:{})</p>
      
      <p>[2014-11-16 14:53:52,918: DEBUG/MainProcess] Mediator: Running callback for task: utils.tasks.<strong>do_things_2</strong>[a1c09645-32fb-4399-802b-60ca826fa6bc]</p>
      
      <p>[2014-11-16 14:53:52,918: DEBUG/MainProcess] TaskPool: Apply  (args:('utils.tasks.<strong>do_things_2</strong>', 'a1c09645-32fb-4399-802b-60ca826fa6bc', [u'0301010101', u'1'], {}, {'utc': True, 'is_eager': False, 'chord': None, 'group': None, 'args': [u'0301010101', u'1'], 'retries': 0, 'delivery_info': {'priority': None, 'routing_key': u'celery', 'exchange': u'celery'}, 'expires': None, 'task': 'utils.tasks.do_things_2', 'callbacks': None, 'errbacks': None, 'hostname': '*********************', 'taskset': None, 'kwargs': {}, 'eta': '2014-11-16T05:53:52.851516', 'id': 'a1c09645-32fb-4399-802b-60ca826fa6bc'}) kwargs:{})</p>
      
      <p>[2014-11-16 14:53:52,918: DEBUG/MainProcess] Mediator: Running callback for task: utils.tasks.<strong>do_things_3</strong>[5a66f885-baf2-49ab-b82f-733d2b68fe7b]</p>
      
      <p>[2014-11-16 14:53:52,918: DEBUG/MainProcess] TaskPool: Apply  (args:('utils.tasks.<strong>do_things_3</strong>', '5a66f885-baf2-49ab-b82f-733d2b68fe7b', [u'0301010101', u'1', u'1'], {}, {'utc': True, 'is_eager': False, 'chord': None, 'group': None, 'args': [u'0301010101', u'1', u'1'], 'retries': 0, 'delivery_info': {'priority': None, 'routing_key': u'celery', 'exchange': u'celery'}, 'expires': None, 'task': 'utils.tasks.do_things_3', 'callbacks': None, 'errbacks': None, 'hostname': '*************************', 'taskset': None, 'kwargs': {}, 'eta': '2014-11-16T05:53:52.852527', 'id': '5a66f885-baf2-49ab-b82f-733d2b68fe7b'}) kwargs:{})</p>
    </blockquote>
  </blockquote>
  
  <ul>
  <li><p><b>I've checked that do_things_1, do_thins_2, do_things_3 executed well from the browser</b></p></li>
  <li><p><i>Check number of tasks and worker</i> <b>(As you can see, task is not reduced from the queue)</b></p></li>
  </ul>
  
  <blockquote>
    <p>$ sudo rabbitmqctl list_queues name messages consumers | grep celery</p>
    
    <blockquote>
      <p><strong>celery 3   1</strong>       (3 tasks, 1 worker)</p>
    </blockquote>
  </blockquote>
  
  <ul>
  <li><i><b>Repeat</b> to execute <strong>do_things_1, do_things_2, do_things_3</strong>(2nd attempts)</i></li>
  </ul>
  
  <blockquote>
    <blockquote>
      <p>[2014-11-16 15:27:54,060: DEBUG/MainProcess] <strong>Task accepted: utils.tasks.do_things_1</strong>[027918df-a6ef-4712-a8c8-5b380d5bd0f6] pid:23793</p>
      
      <p>[2014-11-16 15:27:54,060: INFO/MainProcess] Got task from broker: utils.tasks.<strong>do_things_1</strong>[2ea06e92-c617-460e-9275-98d4c4f79394] eta:[2014-11-16 15:27:55.048622+09:00]</p>
      
      <p>[2014-11-16 15:27:54,060: DEBUG/MainProcess] consumer: basic.qos: <strong>prefetch_count->5</strong></p>
      
      <p>[2014-11-16 15:27:54,063: INFO/MainProcess] <strong>Task utils.tasks.do_things_1[027918df-a6ef-4712-a8c8-5b380d5bd0f6] succeeded in 1415464878.25s: None</strong></p>
      
      <p>[2014-11-16 15:27:54,063: INFO/MainProcess] Got task from broker: utils.tasks.<strong>do_things_2</strong>[cad7b687-7ef6-4f99-a06e-4a038369837d] eta:[2014-11-16 15:27:55.061913+09:00]</p>
      
      <p>[2014-11-16 15:27:54,063: DEBUG/MainProcess] consumer: basic.qos: <strong>prefetch_count->6</strong></p>
      
      <p>[2014-11-16 15:27:54,065: DEBUG/MainProcess] <strong>Task accepted: utils.tasks.do_things_2[a1c09645-32fb-4399-802b-60ca826fa6bc] pid:23793</strong></p>
      
      <p>[2014-11-16 15:27:54,066: INFO/MainProcess] Got task from broker: utils.tasks.<strong>do_things_3</strong>[ceee2b27-5cc0-45cc-9a00-e15a361fa92f] eta:[2014-11-16 15:27:55.064312+09:00]</p>
      
      <p>[2014-11-16 15:27:54,066: DEBUG/MainProcess] consumer: basic.qos: <strong>prefetch_count->7</strong></p>
      
      <p>[2014-11-16 15:27:55,068: DEBUG/MainProcess] consumer: basic.qos: <strong>prefetch_count->4</strong></p>
      
      <p>[2014-11-16 15:27:55,101: DEBUG/MainProcess] Mediator: Running callback for task: utils.tasks.<strong>do_things_1</strong>[2ea06e92-c617-460e-9275-98d4c4f79394]</p>
      
      <p>[2014-11-16 15:27:55,101: DEBUG/MainProcess] TaskPool: Apply  (args:('utils.tasks.<strong>do_things_1</strong>', '2ea06e92-c617-460e-9275-98d4c4f79394', [u'0301010101', u'1'], {}, {'utc': True, 'is_eager': False, 'chord': None, 'group': None, 'args': [u'0301010101', u'1'], 'retries': 0, 'delivery_info': {'priority': None, 'routing_key': u'celery', 'exchange': u'celery'}, 'expires': None, 'task': 'utils.tasks.do_things_1', 'callbacks': None, 'errbacks': None, 'hostname': '******************************', 'taskset': None, 'kwargs': {}, 'eta': '2014-11-16T06:27:55.048622', 'id': '2ea06e92-c617-460e-9275-98d4c4f79394'}) kwargs:{})</p>
      
      <p>[2014-11-16 15:27:55,105: DEBUG/MainProcess] Mediator: Running callback for task: utils.tasks.<strong>do_things_2</strong>[cad7b687-7ef6-4f99-a06e-4a038369837d]</p>
      
      <p>[2014-11-16 15:27:55,105: DEBUG/MainProcess] TaskPool: Apply  (args:('utils.tasks.<strong>do_things_2</strong>', 'cad7b687-7ef6-4f99-a06e-4a038369837d', [u'0301010101', u'1'], {}, {'utc': True, 'is_eager': False, 'chord': None, 'group': None, 'args': [u'0301010101', u'1'], 'retries': 0, 'delivery_info': {'priority': None, 'routing_key': u'celery', 'exchange': u'celery'}, 'expires': None, 'task': 'utils.tasks.do_things_2', 'callbacks': None, 'errbacks': None, 'hostname': '*************************', 'taskset': None, 'kwargs': {}, 'eta': '2014-11-16T06:27:55.061913', 'id': 'cad7b687-7ef6-4f99-a06e-4a038369837d'}) kwargs:{})</p>
      
      <p>[2014-11-16 15:27:55,105: DEBUG/MainProcess] Mediator: Running callback for task: utils.tasks.<strong>do_things_3</strong>[ceee2b27-5cc0-45cc-9a00-e15a361fa92f]</p>
      
      <p>[2014-11-16 15:27:55,106: DEBUG/MainProcess] TaskPool: Apply  (args:('utils.tasks.<strong>do_things_3</strong>', 'ceee2b27-5cc0-45cc-9a00-e15a361fa92f', [u'0301010101', u'1', u'1'], {}, {'utc': True, 'is_eager': False, 'chord': None, 'group': None, 'args': [u'0301010101', u'1', u'1'], 'retries': 0, 'delivery_info': {'priority': None, 'routing_key': u'celery', 'exchange': u'celery'}, 'expires': None, 'task': 'utils.tasks.do_things_3', 'callbacks': None, 'errbacks': None, 'hostname': '*******************************', 'taskset': None, 'kwargs': {}, 'eta': '2014-11-16T06:27:55.064312', 'id': 'ceee2b27-5cc0-45cc-9a00-e15a361fa92f'}) kwargs:{})</p>
    </blockquote>
  </blockquote>
  
  <ul>
  <li><p><b>I've checked that do_things_1, do_thins_2, do_things_3 executed well from the browser</b></p></li>
  <li><p><i>Check number of tasks and worker</i> <b>(As you can see, task is reduced partially)</b></p></li>
  </ul>
  
  <blockquote>
    <p>$ sudo rabbitmqctl list_queues name messages consumers | grep celery</p>
    
    <blockquote>
      <p><strong>celery 4   1</strong>       (4 tasks, 1 worker)</p>
    </blockquote>
  </blockquote>
  
  <ul>
  <li><p><i><b>Repeat</b> to execute <strong>do_things_1, do_things_2, do_things_3</strong> (3rd attempts)</i></p></li>
  <li><p><b>Celery didn't log anything and do_things_1, do_thins_2, do_things_3 not executed!</b></p></li>
  <li><p><i>Check number of tasks and worker</i> <b>(As you can see, task is increased)</b></p></li>
  </ul>
  
  <blockquote>
    <p>$ sudo rabbitmqctl list_queues name messages consumers | grep celery</p>
    
    <blockquote>
      <p><strong>celery 7   1</strong>       (7 tasks, 1 worker)</p>
    </blockquote>
  </blockquote>
  
  <ul>
  <li>When I <b>terminate it by "Ctrl+C"</b>, it logs like following</li>
  </ul>
  
  <blockquote>
    <p>celeryd: Warm shutdown (MainProcess)</p>
    
    <blockquote>
      <p>[2014-11-16 16:15:52,922: DEBUG/MainProcess] Stopping celery.worker.consumer.Consumer...</p>
      
      <p>[2014-11-16 16:15:52,923: DEBUG/MainProcess] consumer: Stopping consumers...</p>
      
      <p>[2014-11-16 16:15:52,923: DEBUG/MainProcess] Stopping celery.worker.mediator.Mediator...</p>
      
      <p>[2014-11-16 16:15:53,638: DEBUG/MainProcess] Stopping celery.concurrency.processes.TaskPool...</p>
      
      <p>[2014-11-16 16:15:53,638: INFO/MainProcess] Task utils.tasks.<strong>do_things_2</strong>[a1c09645-32fb-4399-802b-60ca826fa6bc] succeeded in 1415467757.76s: None</p>
      
      <p>[2014-11-16 16:15:53,639: DEBUG/MainProcess] <strong>Task accepted: utils.tasks.do_things_3[5a66f885-baf2-49ab-b82f-733d2b68fe7b] pid:23793</strong></p>
      
      <p>[2014-11-16 16:15:53,639: INFO/MainProcess] <strong>Task utils.tasks.do_things_3[5a66f885-baf2-49ab-b82f-733d2b68fe7b] succeeded in 1415467757.75s: None</strong></p>
      
      <p>[2014-11-16 16:15:53,640: DEBUG/MainProcess] <strong>Task accepted: utils.tasks.do_things_1[2ea06e92-c617-460e-9275-98d4c4f79394] pid:23793</strong></p>
      
      <p>[2014-11-16 16:15:53,640: INFO/MainProcess] <strong>Task utils.tasks.do_things_1[2ea06e92-c617-460e-9275-98d4c4f79394] succeeded in 1415465715.65s: None</strong></p>
      
      <p>[2014-11-16 16:15:53,640: DEBUG/MainProcess] <strong>Task accepted: utils.tasks.do_things_2[cad7b687-7ef6-4f99-a06e-4a038369837d] pid:23793</strong></p>
      
      <p>[2014-11-16 16:15:53,641: INFO/MainProcess] <strong>Task utils.tasks.do_things_2[cad7b687-7ef6-4f99-a06e-4a038369837d] succeeded in 1415465715.64s: None</strong></p>
      
      <p>[2014-11-16 16:15:53,641: DEBUG/MainProcess] <strong>Task accepted: utils.tasks.do_things_3[ceee2b27-5cc0-45cc-9a00-e15a361fa92f] pid:23793</strong></p>
      
      <p>[2014-11-16 16:15:53,642: INFO/MainProcess] Task utils.tasks.update_apartboard_1st_load_page_cache[ceee2b27-5cc0-45cc-9a00-e15a361fa92f] succeeded in 1415465715.63s: None</p>
    </blockquote>
  </blockquote>
  
  <ul>
  <li><p><b> do_things_1, do_things_2, do_things_3 not executed</b> (Check from the browser)</p></li>
  <li><p><i>Check number of tasks and worker</i> <b>(As you can see, task is reduced from the queue)</b></p></li>
  </ul>
  
  <blockquote>
    <p>$ sudo rabbitmqctl list_queues name messages consumers | grep celery</p>
    
    <blockquote>
      <p><strong>celery 3   0</strong>       (3 tasks, 0 worker)</p>
    </blockquote>
  </blockquote>
  
  <ul>
  <li>Purge task queue</li>
  </ul>
  
  <blockquote>
    <p>$ ./manage.py celeryctl purge</p>
    
    <p>$ sudo rabbitmqctl list_queues name messages consumers | grep celery</p>
    
    <blockquote>
      <p><strong>celery 0   0</strong>       (0 tasks, 0 worker)</p>
    </blockquote>
  </blockquote>