Volume can't be attached to instance because of rabbit failures after reboot primary controller

[Andrey Sledzinskiy]

{

    "build_id": "2014-09-13_14-34-19",
    "ostf_sha": "64cb59c681658a7a55cc2c09d079072a41beb346",
    "build_number": "6",
    "auth_required": true,
    "api": "1.0",
    "nailgun_sha": "b8d8189cc37d6d1b26f4479be6be7313beefb1c8",
    "production": "docker",
    "fuelmain_sha": "d7ed7973034bde73d3f42c000984423b59b2312b",
    "astute_sha": "f5fbd89d1e0e1f22ef9ab2af26da5ffbfbf24b13",
    "feature_groups": [
        "experimental"
    ],
    "release": "5.1",
    "release_versions": {
        "2014.1.1-5.1": {
            "VERSION": {
                "build_id": "2014-09-13_14-34-19",
                "ostf_sha": "64cb59c681658a7a55cc2c09d079072a41beb346",
                "build_number": "6",
                "api": "1.0",
                "nailgun_sha": "b8d8189cc37d6d1b26f4479be6be7313beefb1c8",
                "production": "docker",
                "fuelmain_sha": "d7ed7973034bde73d3f42c000984423b59b2312b",
                "astute_sha": "f5fbd89d1e0e1f22ef9ab2af26da5ffbfbf24b13",
                "feature_groups": [
                    "experimental"
                ],
                "release": "5.1",
                "fuellib_sha": "395fd9d20a003603cc9ad26e16cb13c1c45e24e6"
            }
        }
    },
    "fuellib_sha": "395fd9d20a003603cc9ad26e16cb13c1c45e24e6"

}

Steps:
1. Create next cluster - Neutron Vlan, CentOS, HA, 3 controllers, 2 compute, 1 cinder
2. Deploy cluster
3. After deployment reboot primary controller

Expected - test passed
Actual - test on volume creation and test on Check network connectivity from instance via floating IP failed
Lots of errors in logs on cinder node in cinder-volume log:
2014-09-15 09:28:33 ERROR

oslo.messaging._drivers.common [req-88fae43e-aaf7-4883-8ee0-2a84736f3a2b a606b0b992b64a7995acf84171f2c7a2 13b880940c604b0a80682a42353e8dea - - -] ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n incoming.message))\n', ' File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n return self._do_dispatch(endpoint, method, ctxt, args)\n', ' File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n result = getattr(endpoint, method)(ctxt, **new_args)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 778, in initialize_connection\n volume = self.db.volume_get(context, volume_id)\n', ' File "/usr/lib/python2.6/site-packages/cinder/db/api.py", line 205, in volume_get\n return IMPL.volume_get(context, volume_id)\n', ' File "/usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py", line 137, in wrapper\n return f(*args, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py", line 1154, in volume_get\n return _volume_get(context, volume_id)\n', ' File "/usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py", line 137, in wrapper\n return f(*args, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py", line 1147, in _volume_get\n raise exception.VolumeNotFound(volume_id=volume_id)\n', 'VolumeNotFound: Volume acd20eeb-5e29-473b-bd39-a692866aa4ac could not be found.\n']

2014-09-15 09:28:33 ERROR

oslo.messaging._drivers.common [req-88fae43e-aaf7-4883-8ee0-2a84736f3a2b a606b0b992b64a7995acf84171f2c7a2 13b880940c604b0a80682a42353e8dea - - -] Returning exception Volume acd20eeb-5e29-473b-bd39-a692866aa4ac could not be found. to caller

On first controller (node-4):
2014-09-14 13:11:06 ERROR

oslo.messaging._drivers.impl_rabbit [-] Failed to consume message from queue: (0, 0): (320) CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit Traceback (most recent call last):
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.6/site-packages/oslo/messaging/_drivers/impl_rabbit.py", line 648, in ensure
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit return method(*args, **kwargs)
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.6/site-packages/oslo/messaging/_drivers/impl_rabbit.py", line 737, in _consume
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit return self.connection.drain_events(timeout=timeout)
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.6/site-packages/kombu/connection.py", line 279, in drain_events
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit return self.transport.drain_events(self.connection, **kwargs)
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.6/site-packages/kombu/transport/pyamqp.py", line 91, in drain_events
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit return connection.drain_events(**kwargs)
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.6/site-packages/amqp/connection.py", line 320, in drain_events
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit return amqp_method(channel, args)
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.6/site-packages/amqp/connection.py", line 526, in _close
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit (class_id, method_id), ConnectionError)
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit ConnectionForced: (0, 0): (320) CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'
2014-09-14 12:11:06.231 2484 TRACE oslo.messaging._drivers.impl_rabbit

[Ivan Kolodyazhny (e0ne)]

Some more logs from Sergey:

2014-09-15 13:34:51.558 27538 DEBUG cinder.openstack.common.lockutils [req-481bfc00-7542-4d52-9be7-d7f0e50551f1 a606b0b992b64a7995acf84171f2c7a2 13b880940c604b0a80682a42353e8dea - - -] Released file lock "dc4a9cf9-1d4f-456d-8d8f-cba8a3d27042" at /var/lib/cinder/tmp/cinder-dc4a9cf9-1d4f-456d-8d8f-cba8a3d27042 for method "do_attach"... inner /usr/lib/python2.6/site-packages/cinder/openstack/common/lockutils.py:239

2014-09-15 13:35:21.681 27538 DEBUG cinder.volume.manager [req-ff61241f-ee31-416c-b9a0-60dba331ebb8 a606b0b992b64a7995acf84171f2c7a2 13b880940c604b0a80682a42353e8dea - - -] volume dc4a9cf9-1d4f-456d-8d8f-cba8a3d27042: removing export terminate_connection /usr/lib/python2.6/site-packages/cinder/volume/manager.py:868

volume is deleted after 30s
 API Cinder:
2014-09-15 13:34:40.382 1759 INFO cinder.api.openstack.wsgi [req-69d2913f-ddc1-4585-baf5-458a6eaf0221 a606b0b992b64a7995acf84171f2c7a2 13b880940c604b0a80682a42353e8dea - - -] GET http://10.108.2.5:8776/v1/13b880940c604b0a80682a42353e8dea/volumes/dc4a9cf9-1d4f-456d-8d8f-cba8a3d27042

2014-09-15 13:35:16.574 1759 DEBUG routes.middleware [req-ff61241f-ee31-416c-b9a0-60dba331ebb8 a606b0b992b64a7995acf84171f2c7a2 13b880940c604b0a80682a42353e8dea - - -] Matched POST /13b880940c604b0a80682a42353e8dea/volumes/dc4a9cf9-1d4f-456d-8d8f-cba8a3d27042/action __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:100

30 seconds is not enough for volume creation is some environments, so looks like a test issue.

Provided logs in a bug report shows a different issue.