restart of zaqar breaks usage of existing queue

Bug #1477181 reported by Valeriy Ponomaryov on 2015-07-22
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
zaqar
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  Edit
Everyone can see this information.

Other bug subscribers