openstack cinder volume metadata AttributeError

[alkersan]

Hi. I'm trying to setup Flocker within OpenStack. Everything was fine at first: I've setup Flocker cluster, with loopback backend on the nodes for a test. Now when I've switched backends to OpenStack, I receive exception during node start:

57156654-bfe5-4857-a1f1-e546832ef6d7 -> /1
2016-08-22 20:45:42.100865Z
  message_type: 'twisted:log'
  error: False
  message: 'Log opened.'

0e74ee60-39ae-428e-975e-af921539bdb4 -> /1
2016-08-22 20:45:42.260425Z
  action_type: 'flocker:node:script:get_external_ip'
  action_status: 'started'
  host: '10.191.41.152'
  port: 4524

0e74ee60-39ae-428e-975e-af921539bdb4 -> /2
2016-08-22 20:45:42.262172Z
  action_type: 'flocker:node:script:get_external_ip'
  action_status: 'succeeded'
  local_ip: '10.191.41.151'

271c6b55-89ae-4223-a846-9207b9ac812d -> /1
2016-08-22 20:45:42.270869Z
  action_type: 'fsm:initialize'
  action_status: 'started'
  fsm_identifier: '<flocker.node._loop.ConvergenceLoop object at 0x7f7eda61ae90>'
  fsm_state: '<ConvergenceLoopStates=STOPPED>'

8e1d8172-308f-4fd2-ae9a-b1f15668813f -> /1
2016-08-22 20:45:42.272076Z
  action_type: 'fsm:initialize'
  action_status: 'started'
  fsm_identifier: '<flocker.node._loop.ClusterStatus object at 0x7f7eda637210>'
  fsm_state: '<ClusterStatusStates=DISCONNECTED>'

5637bb30-3ec0-4ff3-9b8b-812b41dbb0ad -> /1
2016-08-22 20:45:42.273282Z
  message_type: 'twisted:log'
  error: False
  message: 'Starting factory <twisted.internet.protocol.ReconnectingClientFactory instance at 0x7f7eda621c20>'

96f6a1bd-981d-424f-8568-5b92f9731373 -> /1
2016-08-22 20:45:42.279021Z
  message_type: 'twisted:log'
  error: False
  message: "AgentAMP connection established (HOST:IPv4Address(TCP, 'XX.XX.XX.XX', 45260) PEER:IPv4Address(TCP, 'XX.XX.XX.XX', 4524))"

147a7946-c22a-47da-933c-d0d92f1618c1 -> /1
2016-08-22 20:45:42.280709Z
  action_type: 'fsm:transition'
  action_status: 'started'
  fsm_identifier: '<flocker.node._loop.ClusterStatus object at 0x7f7eda637210>'
  fsm_input: '<ClusterStatusInputs=CONNECTED_TO_CONTROL_SERVICE>'
  fsm_rich_input: '<_ConnectedToControlService>'
  fsm_state: '<ClusterStatusStates=DISCONNECTED>'

147a7946-c22a-47da-933c-d0d92f1618c1 -> /2
2016-08-22 20:45:42.281281Z
  action_type: 'fsm:transition'
  action_status: 'succeeded'
  fsm_next_state: '<ClusterStatusStates=IGNORANT>'
  fsm_output: ['<ClusterStatusOutputs=STORE_CLIENT>']

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/1
2016-08-22 20:45:43.275002Z
  action_type: 'eliot:remote_task'
  action_status: 'started'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/1
2016-08-22 20:45:43.284150Z
  action_type: 'fsm:transition'
  action_status: 'started'
  fsm_identifier: '<flocker.node._loop.ClusterStatus object at 0x7f7eda637210>'
  fsm_input: '<ClusterStatusInputs=STATUS_UPDATE>'
  fsm_rich_input: '<_StatusUpdate>'
  fsm_state: '<ClusterStatusStates=IGNORANT>'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/1
2016-08-22 20:45:43.285476Z
  action_type: 'fsm:transition'
  action_status: 'started'
  fsm_identifier: '<flocker.node._loop.ConvergenceLoop object at 0x7f7eda61ae90>'
  fsm_input: '<ConvergenceLoopInputs=STATUS_UPDATE>'
  fsm_rich_input: '<_ClientStatusUpdate>'
  fsm_state: '<ConvergenceLoopStates=STOPPED>'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/1
2016-08-22 20:45:43.286619Z
  action_type: 'flocker:agent:converge'
  action_status: 'started'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/1
2016-08-22 20:45:43.287368Z
  action_type: 'flocker:agent:discovery'
  action_status: 'started'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/2
2016-08-22 20:45:43.288316Z
  message_type: 'flocker:node:agents:blockdevice:list_volumes'
  count: 1
  function: '_discover_raw_state'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/3/1
2016-08-22 20:45:43.289919Z
  action_type: 'flocker:node:agents:blockdevice:openstack'
  action_status: 'started'
  operation: ['list', [], {}]

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/3/2
2016-08-22 20:45:43.417232Z
  message_type: 'twisted:log'
  error: False
  message: 'REQ: curl -g -i --insecure -X GET http://XX.XX.XX.XX:8774/v2/cc3a849c8aad46f8ac8d6939e06b6aaa/servers/detail -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}3f84fc4c1c0f4a8e992890ae999ff9d93d03da6a"'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/3/3
2016-08-22 20:45:43.992590Z
  message_type: 'twisted:log'
  error: False
  message: 'RESP: [200] Content-Type: application/json Content-Length: 53727 X-Compute-Request-Id: req-691469f2-676a-4247-8642-150ff8458740 Date: Mon, 22 Aug 2016 20:45:43 GMT Connection: close '

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/3/4
2016-08-22 20:45:43.994172Z
  message_type: 'twisted:log'
  error: False
  message: 'RESP BODY: {"servers": [{"status": "ACTIVE", "hostId": "...",
...
" **** Here goes huge JSON response from nova with all servers **** "
...]}'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/3/5
2016-08-22 20:45:43.995033Z
  message_type: 'twisted:log'
  error: False
  message: ''

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/3/6
2016-08-22 20:45:43.998272Z
  message_type: 'twisted:log'
  error: False
  message: 'GET call to compute for http://XX.XX.XX.XX:8774/v2/cc3a849c8aad46f8ac8d6939e06b6aaa/servers/detail used request id req-691469f2-676a-4247-8642-150ff8458740'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/3/7
2016-08-22 20:45:44.013568Z
  action_type: 'flocker:node:agents:blockdevice:openstack'
  action_status: 'succeeded'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/4/1
2016-08-22 20:45:44.299957Z
  action_type: 'flocker:node:agents:blockdevice:openstack'
  action_status: 'started'
  operation: ['list', [], {'detailed': False}]

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/4/2
2016-08-22 20:45:44.523136Z
  action_type: 'flocker:node:agents:blockdevice:openstack'
  action_status: 'succeeded'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/2/5
2016-08-22 20:45:44.525073Z
  action_type: 'flocker:agent:discovery'
  action_status: 'failed'
  exception: 'exceptions.AttributeError'
  reason: 'metadata'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/3
2016-08-22 20:45:44.526244Z
  message_type: 'eliot:traceback'
  exception: 'exceptions.AttributeError'
  reason: 'metadata'
  traceback: "Traceback: <type 'exceptions.AttributeError'>: metadata
           |  /opt/flocker/local/lib/python2.7/site-packages/machinist/_logging.py:102:receive
           |  /opt/flocker/local/lib/python2.7/site-packages/machinist/_fsm.py:534:receive
           |  /opt/flocker/local/lib/python2.7/site-packages/machinist/_fsm.py:592:output
           |  /opt/flocker/local/lib/python2.7/site-packages/flocker/node/_loop.py:529:output_CONVERGE
           |  --- <exception caught here> ---
           |  /opt/flocker/local/lib/python2.7/site-packages/twisted/internet/defer.py:150:maybeDeferred
           |  /opt/flocker/local/lib/python2.7/site-packages/flocker/node/agents/blockdevice.py:1798:discover_state
           |  /opt/flocker/local/lib/python2.7/site-packages/flocker/node/agents/blockdevice.py:1345:_count_calls
           |  /opt/flocker/local/lib/python2.7/site-packages/flocker/node/agents/blockdevice.py:1744:_discover_raw_state
           |  /opt/flocker/local/lib/python2.7/site-packages/flocker/node/agents/cinder.py:534:list_volumes
           |  /opt/flocker/local/lib/python2.7/site-packages/flocker/node/agents/cinder.py:746:_is_cluster_volume
           |  /opt/flocker/local/lib/python2.7/site-packages/cinderclient/openstack/common/apiclient/base.py:505:__getattr__
           |  "

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/4
2016-08-22 20:45:44.526981Z
  message_type: 'flocker:node:_loop:delay'
  current_wait: 0.1
  log_level: 'INFO'
  message: 'Intentionally delaying the next iteration of the convergence loop to avoid RequestLimitExceeded.'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/5
2016-08-22 20:45:44.527847Z
  message_type: 'flocker:node:_loop:CONVERGE:delay'
  delay: 0.1
  log_level: 'INFO'
  message: 'Delaying until next convergence loop.'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/6/1
2016-08-22 20:45:44.529310Z
  action_type: 'fsm:transition'
  action_status: 'started'
  fsm_identifier: '<flocker.node._loop.ConvergenceLoop object at 0x7f7eda61ae90>'
  fsm_input: '<ConvergenceLoopInputs=SLEEP>'
  fsm_rich_input: '<_Sleep>'
  fsm_state: '<ConvergenceLoopStates=CONVERGING>'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/6/2
2016-08-22 20:45:44.530575Z
  action_type: 'fsm:transition'
  action_status: 'succeeded'
  fsm_next_state: '<ConvergenceLoopStates=SLEEPING>'
  fsm_output: ['<ConvergenceLoopOutputs=SCHEDULE_WAKEUP>']

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/2/7
2016-08-22 20:45:44.531377Z
  action_type: 'flocker:agent:converge'
  action_status: 'succeeded'

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/2/3
2016-08-22 20:45:44.532240Z
  action_type: 'fsm:transition'
  action_status: 'succeeded'
  fsm_next_state: '<ConvergenceLoopStates=SLEEPING>'
  fsm_output: ['<ConvergenceLoopOutputs=STORE_INFO>',
            |  '<ConvergenceLoopOutputs=CONVERGE>']

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/2/3
2016-08-22 20:45:44.533140Z
  action_type: 'fsm:transition'
  action_status: 'succeeded'
  fsm_next_state: '<ClusterStatusStates=KNOWLEDGEABLE>'
  fsm_output: ['<ClusterStatusOutputs=UPDATE_STATUS>']

ee0b93f8-e8d5-49bf-ba52-f06c7a48d3ae -> /2/2/3
2016-08-22 20:45:44.533866Z
  action_type: 'eliot:remote_task'
  action_status: 'succeeded'

It looks like request to Nova for servers details succeded, as I see it's response object in logs, right before metadata attributeError

Any suggestions how to troubleshoot this?

[alkersan]

I've looked deeper and found possible error point here: volumes retrieved with detailed=False seems to have metadata field missing. I've built Flocker locally with detailed=True and it worked.

[wallnerryan]

@alkersan yes we just found this ourselves as well. the Cinderv1 api doesnt do this but v2 does. @wallrj has been working on this and will post here when we fix.

[wallnerryan]

And thanks for troubleshooting 👍.

[wallrj]

Fixed in #2892 and released last week in 1.15.0.

• https://docs.clusterhq.com/en/latest/releasenotes/index.html#v1-15-0