Bug 1091716

What appears in the Cinder api and volume logs when this happens?

From the strace of the c-api:

26357 recvfrom(10, "\1\0\1\0\0\0]\0<\0<\0011\0\0\0\0\0\0\0009\0&reply_f8e80f44ee2a4b7c88fa73708809d92b&reply_f8e80f44ee2a4b7c88fa73708809d92b\316\2\0\1\0\0\0+\0<\0\0\0\0\0\0\0\0\10\247\370\0\20application/json\5utf-8\0\0\0\0\2\0
\316\3\0\1\0\0\10\247{\"oslo.message\": \"{\\\"_unique_id\\\": \\\"613265ac51494685a8021c5a7d10864e\\\", \\\"failure\\\": \\\"{\\\\\\\"args\\\\\\\": [\\\\\\\"Failed to create iscsi target for volume volume-3d0618b3-73d2-45c6-b2f
8-4d87dc0c30db.\\\\\\\"], \\\\\\\"module\\\\\\\": \\\\\\\"cinder.brick.exception\\\\\\\", \\\\\\\"kwargs\\\\\\\": {\\\\\\\"code\\\\\\\": 500, \\\\\\\"volume_id\\\\\\\": \\\\\\\"volume-3d0618b3-73d2-45c6-b2f8-4d87dc0c30db\\\\\\\"
}, \\\\\\\"message\\\\\\\": \\\\\\\"Failed to create iscsi target for volume volume-3d0618b3-73d2-45c6-b2f8-4d87dc0c30db.\\\\\\\", \\\\\\\"tb\\\\\\\": [\\\\\\\"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/sit
e-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-pac
kages/cinder/volume/manager.py\\\\\\\\\\\\\\\", line 783, in initialize_connection\\\\\\\\n    volume)\\\\\\\\n\\\\\\\", \\\\\\\"  File \\\\\\\\\\\\\\\"/usr/lib/python2.6/site-packages/cinder/volume/drivers/lvm.py\\\\\\\\\\\\\\\
", line 524, in create_export\\\\\\\\n    return self._create_export(context, volume)\\\\\\\\n\\\\\\\", \\\\\\\"  File \\\\\\\\\\\\\\\"/usr/lib/python2.6/site-packages/cinder/volume/drivers/lvm.py\\\\\\\\\\\\\\\", line 533, in _
create_export\\\\\\\\n    data = self.target_helper.create_export(context, volume, volume_path)\\\\\\\\n\\\\\\\", \\\\\\\"  File \\\\\\\\\\\\\\\"/usr/lib/python2.6/site-packages/cinder/volume/iscsi.py\\\\\\\\\\\\\\\", line 53, i
n create_export\\\\\\\\n    chap_auth)\\\\\\\\n\\\\\\\", \\\\\\\"  File \\\\\\\\\\\\\\\"/usr/lib/python2.6/site-packages/cinder/brick/iscsi/iscsi.py\\\\\\\\\\\\\\\", line 244, in create_iscsi_target\\\\\\\\n    raise exception.I
SCSITargetCreateFailed(volume_id=vol_id)\\\\\\\\n\\\\\\\", \\\\\\\"ISCSITargetCreateFailed: Failed to create iscsi target for volume volume-3d0618b3-73d2-45c6-b2f8-4d87dc0c30db.\\\\\\\\n\\\\\\\"], \\\\\\\"class\\\\\\\": \\\\\\\"
ISCSITargetCreateFailed\\\\\\\"}\\\", \\\"result\\\": null, \\\"_msg_id\\\": \\\"9d098b746bd8423a8747394d017b4624\\\"}\", \"oslo.version\": \"2.0\"}\316", 65536, 0, NULL, NULL) = 2375

Looks like it got an rpc error message from the c-vol,
but it is not logged!! Both the debug and verbose is True in the cinder.conf. 


Really the c-api send the error message to n-api:
26357 sendto(16, "HTTP/1.1 500 Internal Server Error\r\nContent-Length: 128\r\nContent-Type: application/json; charset=UTF-8\r\nX-Compute-Request-Id: req-3ae53594-0513-4a7d-9a96-9a266bae8f06\r\nX-Openstack-Request-Id: req-3ae53594-0513-4a7d-9a96-9a266bae8f06\r\nDate: Tue, 29 Apr 2014 08:12:47 GMT\r\n\r\n{\"computeFault\": {\"message\": \"The server has either erred or is incapable of performing the requested operation.\", \"code\": 500}}", 401, 0, NULL, 0) = 401

The logging issue was related to c-vol:
 
"  File \"/usr/lib/python2.6/site-packages/cinder/openstack/common/log.py\", line 669, in format\n"
"    return logging.Formatter.format(self, record)\n"
"  File \"/usr/lib64/python2.6/logging/__init__.py\", line 439, in format\n"
"    s = self._fmt % record.__dict__\n"
"KeyError: u'user_name'\n"

The above was stripped from strace, it went to fd=2.

$ openstack-config --get /etc/cinder/cinder.conf DEFAULT logging_context_format_string
%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [%(request_id)s %(user_name)s %(project_name)s] %(instance)s%(message)s

The above option removed, The attachment still not working, but now it logs to the logfile.
2014-04-29 08:44:43.843 31172 ERROR oslo.messaging.rpc.dispatcher [req-6b85ff2c-2841-4c46-8173-bf776ec540a5 75af574f3f40474da0c6aa93acee40d0 06a996d6bd5047368c931c77c7c76237 - - -] Exception during message handling: Failed to create iscsi target for volume volume-3d0618b3-73d2-45c6-b2f8-4d87dc0c30db.
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 783, in initialize_connection
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher     volume)
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/lvm.py", line 524, in create_export
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher     return self._create_export(context, volume)
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/lvm.py", line 533, in _create_export
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher     data = self.target_helper.create_export(context, volume, volume_path)
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/cinder/volume/iscsi.py", line 53, in create_export
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher     chap_auth)
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/cinder/brick/iscsi/iscsi.py", line 244, in create_iscsi_target
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher     raise exception.ISCSITargetCreateFailed(volume_id=vol_id)
2014-04-29 08:44:43.843 31172 TRACE oslo.messaging.rpc.dispatcher ISCSITargetCreateFailed: Failed to create iscsi target for volume volume-3d0618b3-73d2-45c6-b2f8-4d87dc0c30db.

Created attachment 890729 [details]
volume.log

Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /dev/cinder-volumes/volume-b7c223d6-d29e-4032-b743-a089342699c0
Exit code: 22
Stdout: ''
Stderr: 'tgtadm: invalid request\n'


In the log "LUN: 0" not "LUN: 1".

The cinder volume log shows:

ERROR cinder.brick.iscsi.iscsi [req-75f6e209-a9d9-41f5-8769-b3477eaef7bd 22501918310c44e28b9cca280ee55254 3c0ab2cab3d44aa5a895fff8ee913b8f - - -] Failed to create iscsi target for volume id:volume-fb2b7b77-6f2e-45ed-bdc9-6f9d7547cbef. Please ensure your tgtd config file contains 'include /etc/cinder/volumes/*'


/etc/tgt/targets.conf contains:
include /etc/tgt/stack.d/*


But /etc/tgt/stack.d/ does not seem to exist based on the log tarball?

Because it is symbolic link in that setup.

In a packstack setup the 
/etc/tgt/targets.conf:
include /etc/cinder/volumes/*
default-driver iscsi

The same path configured in the 
/usr/share/cinder/cinder-dist.conf:
volumes_dir = /etc/cinder/volumes

The /etc/cinder/cinder.conf does not overrides it.

In simple attach sequence (excluding the create/delete snapshot step), Cinder adds a new entry to the /etc/cinder/volumes.

# lvs
  LV                                          VG             Attr       LSize Pool Origin Data%  Move Log Cpy%Sync Convert                                        
  volume-30968368-38f6-4952-a6dd-cfe333ff442c cinder-volumes -wi-a----- 1.00g     

# cinder snapshot-create 30968368-38f6-4952-a6dd-cfe333ff442c
+---------------------+--------------------------------------+
|       Property      |                Value                 |
+---------------------+--------------------------------------+
|      created_at     |      2014-05-07T10:35:55.885437      |
| display_description |                 None                 |
|     display_name    |                 None                 |
|          id         | b89457d4-1c14-4843-a509-190d3b9e740a |
|       metadata      |                  {}                  |
|         size        |                  1                   |
|        status       |               creating               |
|      volume_id      | 30968368-38f6-4952-a6dd-cfe333ff442c |
+---------------------+--------------------------------------+
# vgs
  VG             #PV #LV #SN Attr   VSize  VFree 
  cinder-volumes   1   4   1 wz--n- 20.60g 16.60g
# lvs
  LV                                             VG             Attr       LSize Pool Origin                                      Data%  Move Log Cpy%Sync Convert
  _snapshot-b89457d4-1c14-4843-a509-190d3b9e740a cinder-volumes swi-a-s--- 1.00g      volume-30968368-38f6-4952-a6dd-cfe333ff442c   0.00                          
1.00g                                                                                  
  volume-30968368-38f6-4952-a6dd-cfe333ff442c    cinder-volumes owi-a-s--- 1.00g                                                                                  
# cinder snapshot-delete b89457d4-1c14-4843-a509-190d3b9e740a
# cinder list
+--------------------------------------+-----------+--------------+------+-------------+----------+--------------------------------------+
|                  ID                  |   Status  | Display Name | Size | Volume Type | Bootable |             Attached to              |
+--------------------------------------+-----------+--------------+------+-------------+----------+--------------------------------------+
| 30968368-38f6-4952-a6dd-cfe333ff442c | available |     None     |  1   |     None    |  false   |                                      |
+--------------------------------------+-----------+--------------+------+-------------+----------+--------------------------------------+
# lvs
  LV                                          VG             Attr       LSize Pool Origin Data%  Move Log Cpy%Sync Convert                                          
  volume-30968368-38f6-4952-a6dd-cfe333ff442c cinder-volumes -wi------- 1.00g 

The volume looses the 'a' (active?) attribute and the /dev/cinder-volumes entry on a snapshot deletion.

It is an upstream issue.
Originally I wanted to reproduce a different issue, but this more simple sequence did not worked.

Appears to be related to LVM activation.

(Below commands are snipped to relevant info.)

# lvs
  LV                                             VG             Attr       LSize Pool Origin                                      Data%  Move Log Cpy%Sync Convert
  _snapshot-757d0311-c47a-4d93-8cb5-0bf160386e4f cinder-volumes swi-a-s--- 1.00g      volume-07f8cd8f-9571-471b-b692-9a3502ee9bb6   0.00                          
  volume-07f8cd8f-9571-471b-b692-9a3502ee9bb6    cinder-volumes owi-a-s--- 1.00g                                                                                  
# cinder snapshot-delete 757d0311-c47a-4d93-8cb5-0bf160386e4f

# vgs
  VG             #PV #LV #SN Attr   VSize  VFree 
  cinder-volumes   1   1   0 wz--n- 20.60g 19.60g
  vg_centosrdo2    1   2   0 wz--n- 11.51g     0 

# lvs
  LV                                          VG             Attr       LSize Pool Origin Data%  Move Log Cpy%Sync Convert
  volume-07f8cd8f-9571-471b-b692-9a3502ee9bb6 cinder-volumes -wi------- 1.00g                                             
  lv_root                                     vg_centosrdo2  -wi-ao---- 7.63g                                             
  lv_swap                                     vg_centosrdo2  -wi-ao---- 3.88g   

(Volume LV is no longer active.)

Nova volume-attach will fail now because tgtd tries to access /dev/cinder-volumes/volume-xxxx which does not exist.  Running "vgchange -a y cinder-volumes" and then nova volume-attach will succeed.

This breaks because the brick vg.delete() code which is used to delete a snapshot or a volume calls "lvchange -y -an cinder-volumes/snapshot-xxxx" which has the effect of deactivating both the snapshot and the source volume.  This may have other implications as well.