restart of zaqar breaks usage of existing queue

Bug #1477181 reported by Valeriy Ponomaryov
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
zaqar
New
Undecided
Unassigned

Bug Description

Steps to reproduce:

1) create queue
2) send there some messages
3) restart zaqar
4) send some messages to queue again

result - messages were not sent and appeared trace with error:
http://paste.openstack.org/show/400124/

or raw variant here:

172.18.198.52 - - [22/Jul/2015 17:15:20] "POST /v1.1/queues/test_queue_for_demo_demo/messages HTTP/1.1" 201 102
2015-07-22 17:15:23.612 1449 DEBUG zaqar.transport.wsgi.v1_1.messages [req-328ecf54-3444-4cd6-8b53-292ed71341ff - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] Messages collection DELETE - queue: test_queue_for_admin_admin, project: 2e05a19040e3488889f8589b90077f2b on_delete /opt/stack/zaqar/zaqar/transport/wsgi/v1_1/messages.py:239
2015-07-22 17:15:23.613 1449 DEBUG zaqar.transport.wsgi.v1_1.messages [req-328ecf54-3444-4cd6-8b53-292ed71341ff - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] POP messages - queue: test_queue_for_admin_admin, project: 2e05a19040e3488889f8589b90077f2b _pop_messages /opt/stack/zaqar/zaqar/transport/wsgi/v1_1/messages.py:277
2015-07-22 17:15:23.613 1449 DEBUG zaqar.openstack.common.lockutils [req-328ecf54-3444-4cd6-8b53-292ed71341ff - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] Got semaphore "pooling:2e05a19040e3488889f8589b90077f2b/test_queue_for_admin_admin" internal_lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:261
2015-07-22 17:15:23.613 1449 DEBUG zaqar.openstack.common.lockutils [req-328ecf54-3444-4cd6-8b53-292ed71341ff - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] Released semaphore "pooling:2e05a19040e3488889f8589b90077f2b/test_queue_for_admin_admin" lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:289
2015-07-22 17:15:23.629 1449 DEBUG zaqar.openstack.common.lockutils [req-328ecf54-3444-4cd6-8b53-292ed71341ff - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] Got semaphore "queuecontroller:exists:2e05a19040e3488889f8589b90077f2b/test_queue_for_admin_admin" internal_lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:261
2015-07-22 17:15:23.629 1449 DEBUG zaqar.openstack.common.lockutils [req-328ecf54-3444-4cd6-8b53-292ed71341ff - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] Released semaphore "queuecontroller:exists:2e05a19040e3488889f8589b90077f2b/test_queue_for_admin_admin" lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:289

172.18.198.52 - - [22/Jul/2015 17:15:23] "DELETE /v1.1/queues/test_queue_for_admin_admin/messages?pop=1 HTTP/1.1" 200 233
2015-07-22 17:15:23.911 1449 DEBUG zaqar.transport.wsgi.v1_1.messages [req-c11041c7-d4fb-495f-836d-452d0f91433e - - - - -] [project_id:da8b6d069b124921b3df5c9854556cb7] Messages collection DELETE - queue: test_queue_for_demo_demo, project: da8b6d069b124921b3df5c9854556cb7 on_delete /opt/stack/zaqar/zaqar/transport/wsgi/v1_1/messages.py:239
2015-07-22 17:15:23.911 1449 DEBUG zaqar.transport.wsgi.v1_1.messages [req-c11041c7-d4fb-495f-836d-452d0f91433e - - - - -] [project_id:da8b6d069b124921b3df5c9854556cb7] POP messages - queue: test_queue_for_demo_demo, project: da8b6d069b124921b3df5c9854556cb7 _pop_messages /opt/stack/zaqar/zaqar/transport/wsgi/v1_1/messages.py:277
2015-07-22 17:15:23.911 1449 DEBUG zaqar.openstack.common.lockutils [req-c11041c7-d4fb-495f-836d-452d0f91433e - - - - -] [project_id:da8b6d069b124921b3df5c9854556cb7] Got semaphore "pooling:da8b6d069b124921b3df5c9854556cb7/test_queue_for_demo_demo" internal_lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:261
2015-07-22 17:15:23.911 1449 DEBUG zaqar.openstack.common.lockutils [req-c11041c7-d4fb-495f-836d-452d0f91433e - - - - -] [project_id:da8b6d069b124921b3df5c9854556cb7] Released semaphore "pooling:da8b6d069b124921b3df5c9854556cb7/test_queue_for_demo_demo" lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:289
2015-07-22 17:15:23.913 1449 DEBUG zaqar.openstack.common.lockutils [req-c11041c7-d4fb-495f-836d-452d0f91433e - - - - -] [project_id:da8b6d069b124921b3df5c9854556cb7] Got semaphore "queuecontroller:exists:da8b6d069b124921b3df5c9854556cb7/test_queue_for_demo_demo" internal_lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:261
2015-07-22 17:15:23.913 1449 DEBUG zaqar.openstack.common.lockutils [req-c11041c7-d4fb-495f-836d-452d0f91433e - - - - -] [project_id:da8b6d069b124921b3df5c9854556cb7] Released semaphore "queuecontroller:exists:da8b6d069b124921b3df5c9854556cb7/test_queue_for_demo_demo" lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:289
172.18.198.52 - - [22/Jul/2015 17:15:23] "DELETE /v1.1/queues/test_queue_for_demo_demo/messages?pop=1 HTTP/1.1" 200 232

restart of zaqar-server:

$ zaqar-server --config-file /etc/zaqar/zaqar.conf & echo $! >/opt/stack/status/stack/zaqar-server.pid; fg || echo "zaqar-server failed to start" | tee "/opt/stack/status/stack/zaqar-server.failure"
[1] 2396
zaqar-server --config-file /etc/zaqar/zaqar.conf
2015-07-22 17:15:45.622 2396 DEBUG zaqar.bootstrap [-] Loading transport driver: wsgi transport /opt/stack/zaqar/zaqar/bootstrap.py:115
2015-07-22 17:15:45.622 2396 DEBUG zaqar.bootstrap [-] Loading storage driver storage /opt/stack/zaqar/zaqar/bootstrap.py:82
2015-07-22 17:15:45.622 2396 DEBUG zaqar.bootstrap [-] Storage pooling enabled storage /opt/stack/zaqar/zaqar/bootstrap.py:84
2015-07-22 17:15:45.623 2396 DEBUG zaqar.bootstrap [-] Loading proxy cache driver cache /opt/stack/zaqar/zaqar/bootstrap.py:103
2015-07-22 17:15:45.627 2396 DEBUG zaqar.bootstrap [-] Loading storage control driver control /opt/stack/zaqar/zaqar/bootstrap.py:97
2015-07-22 17:15:45.644 2396 DEBUG zaqar.bootstrap [-] Loading storage pipeline storage /opt/stack/zaqar/zaqar/bootstrap.py:91
2015-07-22 17:15:45.821 2396 INFO zaqar.transport.wsgi.driver [-] Serving on host 172.18.198.52:8888
2015-07-22 17:16:20.050 2396 DEBUG zaqar.transport.wsgi.v1_1.messages [req-55a9b777-a7c4-4ae4-80c4-fd6c75fdc349 - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] Messages collection POST - queue: test_queue_for_admin_admin, project: 2e05a19040e3488889f8589b90077f2b on_post /opt/stack/zaqar/zaqar/transport/wsgi/v1_1/messages.py:151
2015-07-22 17:16:20.051 2396 DEBUG zaqar.openstack.common.lockutils [req-55a9b777-a7c4-4ae4-80c4-fd6c75fdc349 - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] Got semaphore "pooling:2e05a19040e3488889f8589b90077f2b/test_queue_for_admin_admin" internal_lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:261
2015-07-22 17:16:20.051 2396 DEBUG zaqar.openstack.common.lockutils [req-55a9b777-a7c4-4ae4-80c4-fd6c75fdc349 - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] Released semaphore "pooling:2e05a19040e3488889f8589b90077f2b/test_queue_for_admin_admin" lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:289
2015-07-22 17:16:20.053 2396 DEBUG zaqar.openstack.common.lockutils [req-55a9b777-a7c4-4ae4-80c4-fd6c75fdc349 - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] Got semaphore "pooling:2e05a19040e3488889f8589b90077f2b/test_queue_for_admin_admin" internal_lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:261
2015-07-22 17:16:20.053 2396 DEBUG zaqar.openstack.common.lockutils [req-55a9b777-a7c4-4ae4-80c4-fd6c75fdc349 - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] Released semaphore "pooling:2e05a19040e3488889f8589b90077f2b/test_queue_for_admin_admin" lock /opt/stack/zaqar/zaqar/openstack/common/lockutils.py:289
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages [req-55a9b777-a7c4-4ae4-80c4-fd6c75fdc349 - - - - -] [project_id:2e05a19040e3488889f8589b90077f2b] 'NoneType' object has no attribute '__getitem__'
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages Traceback (most recent call last):
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages File "/opt/stack/zaqar/zaqar/transport/wsgi/v1_1/messages.py", line 176, in on_post
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages if not self._queue_controller.exists(queue_name, project_id):
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages File "/opt/stack/zaqar/zaqar/common/pipeline.py", line 97, in consumer
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages tmp = target(*args, **kwargs)
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages File "/opt/stack/zaqar/zaqar/storage/base.py", line 372, in exists
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages return self._exists(name, project)
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages File "/opt/stack/zaqar/zaqar/storage/pooling.py", line 216, in _exists
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages control = self._get_controller(name, project)
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages File "/opt/stack/zaqar/zaqar/storage/pooling.py", line 531, in get_queue_controller
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages target = self.lookup(queue, project)
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages File "/opt/stack/zaqar/zaqar/storage/pooling.py", line 631, in lookup
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages return self.get_driver(pool_id)
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages File "/opt/stack/zaqar/zaqar/storage/pooling.py", line 646, in get_driver
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages self._drivers[pool_id] = self._init_driver(pool_id, pool_conf)
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages File "/opt/stack/zaqar/zaqar/storage/pooling.py", line 432, in _init_driver
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages conf = utils.dynamic_conf(pool['uri'], pool['options'],
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages TypeError: 'NoneType' object has no attribute '__getitem__'
2015-07-22 17:16:20.053 2396 ERROR zaqar.transport.wsgi.v1_1.messages
172.18.198.52 - - [22/Jul/2015 17:16:20] "POST /v1.1/queues/test_queue_for_admin_admin/messages HTTP/1.1" 503 139

description: updated
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.