Bug 1278451 - [hosted-engine-setup] Deployment over block storage fails with 'Permission denied' error for the HE volume
[hosted-engine-setup] Deployment over block storage fails with 'Permission de...
Status: CLOSED NOTABUG
Product: ovirt-hosted-engine-setup
Classification: oVirt
Component: Plugins.Block (Show other bugs)
1.3.0
x86_64 Unspecified
unspecified Severity urgent (vote)
: ---
: ---
Assigned To: Simone Tiraboschi
Ilanit Stein
integration
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-11-05 09:18 EST by Elad
Modified: 2015-11-17 07:12 EST (History)
13 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2015-11-17 07:12:43 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
ebenahar: planning_ack?
ebenahar: devel_ack?
ebenahar: testing_ack?


Attachments (Terms of Use)
/var/log/ from host (1.03 MB, application/x-gzip)
2015-11-05 09:18 EST, Elad
no flags Details

  None (edit)
Description Elad 2015-11-05 09:18:52 EST
Created attachment 1090099 [details]
/var/log/ from host

Description of problem:
Hosted-engine deployment over block storage (FC/iSCSI), with a clean LUN, fails with 'Permission denied' error for the HE volume.
On file storage (NFS/Glusterfs), deployment succeeds.

Version-Release number of selected component (if applicable):
ovirt-hosted-engine-setup-1.3.0-1.el7ev.noarch

How reproducible:
Always

Steps to Reproduce:
1. Deploy hosted-engine over a clean LUN (FC/iSCSI)


Actual results:

For FC:

vdsm.log:

Thread-107::ERROR::2015-11-05 15:26:36,897::task::866::Storage.TaskManager.Task::(_setError) Task=`cceb857e-7897-4ab6-9fb8-d7d7abedd943`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 873, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 49, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 3214, in prepareImage
    raise se.VolumeDoesNotExist(leafUUID)
VolumeDoesNotExist: Volume does not exist: ('e3cde315-3472-4737-93ca-80bdded69ad4',)

===============================================================

setup log:

2015-11-05 15:26:36 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:936 execute-output: ('/bin/systemctl', 'start', 'sanlock.service') stdout:


2015-11-05 15:26:36 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:941 execute-output: ('/bin/systemctl', 'start', 'sanlock.service') stderr:


2015-11-05 15:26:38 DEBUG otopi.context context._executeMethod:156 method exception
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/otopi/context.py", line 146, in _executeMethod
    method['method']()
  File "/usr/share/ovirt-hosted-engine-setup/scripts/../plugins/ovirt-hosted-engine-setup/sanlock/lockspace.py", line 174, in _misc
    lockspace + '.metadata': md_size,
  File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/lib/storage_backends.py", line 361, in create
    service_size=size)
  File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/lib/storage_backends.py", line 335, in create_volume
    with open(response.path, 'r+') as of:
IOError: [Errno 13] Permission denied: '/var/run/vdsm/storage/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/a3a51a2c-9182-45b7-88dc-ffadc1ca0cad/e3cde315-3472-4737-93ca-80bdded69ad4'
2015-11-05 15:26:38 ERROR otopi.context context._executeMethod:165 Failed to execute stage 'Misc configuration': [Errno 13] Permission denied: '/var/run/vdsm/storage/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/a3a51a2c-9
182-45b7-88dc-ffadc1ca0cad/e3cde315-3472-4737-93ca-80bdded69ad4'



===============================================================

For iSCSI:

vdsm.log:

Thread-131::ERROR::2015-11-05 15:45:17,624::task::866::Storage.TaskManager.Task::(_setError) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 873, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 49, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 3214, in prepareImage
    raise se.VolumeDoesNotExist(leafUUID)
VolumeDoesNotExist: Volume does not exist: ('4a357765-686e-41c6-8463-e52550f7218a',)

===============================================================

setup log:

2015-11-05 15:45:17 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:936 execute-output: ('/bin/systemctl', 'start', 'sanlock.service') stdout:


2015-11-05 15:45:17 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:941 execute-output: ('/bin/systemctl', 'start', 'sanlock.service') stderr:


2015-11-05 15:45:19 DEBUG otopi.context context._executeMethod:156 method exception
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/otopi/context.py", line 146, in _executeMethod
    method['method']()
  File "/usr/share/ovirt-hosted-engine-setup/scripts/../plugins/ovirt-hosted-engine-setup/sanlock/lockspace.py", line 174, in _misc
    lockspace + '.metadata': md_size,
  File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/lib/storage_backends.py", line 361, in create
    service_size=size)
  File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/lib/storage_backends.py", line 335, in create_volume
    with open(response.path, 'r+') as of:
IOError: [Errno 13] Permission denied: '/var/run/vdsm/storage/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/ab515f0c-f7d1-4047-bc8a-1acbe3c6da3e/4a357765-686e-41c6-8463-e52550f7218a'
2015-11-05 15:45:19 ERROR otopi.context context._executeMethod:165 Failed to execute stage 'Misc configuration': [Errno 13] Permission denied: '/var/run/vdsm/storage/2d9a305f-39
2d-48c9-bd48-1a5fcdff6cc9/ab515f0c-f7d1-4047-bc8a-1acbe3c6da3e/4a357765-686e-41c6-8463-e52550f7218a'

===============================================================

Expected results:
Deployment succeeds


Additional info:
/var/log/ from host



[root@green-vdsb ~]# tree /var/run/vdsm/storage/
/var/run/vdsm/storage/                                                                                                                                                                                               
|-- 2d9a305f-392d-48c9-bd48-1a5fcdff6cc9
|   |-- aa8e3487-5ebd-4a33-b347-55277d266814
|   |   `-- bbbb9719-a7c3-428a-95ce-9597b4353650 -> /dev/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/bbbb9719-a7c3-428a-95ce-9597b4353650
|   `-- ab515f0c-f7d1-4047-bc8a-1acbe3c6da3e
|       `-- 4a357765-686e-41c6-8463-e52550f7218a -> /dev/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/4a357765-686e-41c6-8463-e52550f7218a
|-- 5628b18f-757e-4372-bc74-008f9be9ff3a
|   |-- 8c6419a8-768c-4029-950f-45561cd6e82a -> /rhev/data-center/mnt/10.35.160.108:_Storage_elad_4/5628b18f-757e-4372-bc74-008f9be9ff3a/images/8c6419a8-768c-4029-950f-45561cd6e82a
|   |-- a14d1c88-70c1-46b6-90b9-064dd41cc9b4 -> /rhev/data-center/mnt/10.35.160.108:_Storage_elad_4/5628b18f-757e-4372-bc74-008f9be9ff3a/images/a14d1c88-70c1-46b6-90b9-064dd41cc9b4
|   |-- cf5c9a02-aa75-4399-8cad-a613e1fe7bf6 -> /rhev/data-center/mnt/10.35.160.108:_Storage_elad_4/5628b18f-757e-4372-bc74-008f9be9ff3a/images/cf5c9a02-aa75-4399-8cad-a613e1fe7bf6
|   `-- f029d285-6694-42aa-8e57-76936a375620 -> /rhev/data-center/mnt/10.35.160.108:_Storage_elad_4/5628b18f-757e-4372-bc74-008f9be9ff3a/images/f029d285-6694-42aa-8e57-76936a375620
|-- 66c5a4b8-6446-4aa0-95df-26f825114ee9
|   |-- 581f977b-46ab-4bfd-82bd-d7d1e1e23f7b
|   |   `-- 914b6d5b-485a-46e0-aba5-73f3ea160b09 -> /dev/66c5a4b8-6446-4aa0-95df-26f825114ee9/914b6d5b-485a-46e0-aba5-73f3ea160b09
|   `-- 8da357eb-74eb-410e-8e4b-b5765acca6f7
|       `-- 2bbc23da-abdd-4c38-8485-edb6a086478f -> /dev/66c5a4b8-6446-4aa0-95df-26f825114ee9/2bbc23da-abdd-4c38-8485-edb6a086478f
|-- 8c095126-eef1-49a1-b1cd-1e30d1d0af8f
|   |-- a3a51a2c-9182-45b7-88dc-ffadc1ca0cad
|   |   `-- e3cde315-3472-4737-93ca-80bdded69ad4 -> /dev/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/e3cde315-3472-4737-93ca-80bdded69ad4
|   `-- dc47fe12-c71d-46e2-af08-b018384ffd54
|       `-- a0e9248e-62bd-4688-a902-482c4b871c7f -> /dev/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/a0e9248e-62bd-4688-a902-482c4b871c7f
`-- e31aef23-9472-406a-941f-7ae7ffe63d72
    |-- 0d0853c8-72ae-4ee7-8690-d397c0f7fedd
    |   `-- e8348f68-6f98-4691-b2d1-0d6ff1e32a5b -> /dev/e31aef23-9472-406a-941f-7ae7ffe63d72/e8348f68-6f98-4691-b2d1-0d6ff1e32a5b
    `-- f9840ed0-2a70-41f8-9691-e1958cc6babd
        `-- 04027290-bfba-450c-9cbc-72a41380a734 -> /dev/e31aef23-9472-406a-941f-7ae7ffe63d72/04027290-bfba-450c-9cbc-72a41380a734



[root@green-vdsb ~]# tree /rhev/data-center/mnt/
/rhev/data-center/mnt/
|-- 10.35.160.108:_Storage_elad_4
|   |-- 5628b18f-757e-4372-bc74-008f9be9ff3a
|   |   |-- dom_md
|   |   |   |-- ids
|   |   |   |-- inbox
|   |   |   |-- leases
|   |   |   |-- metadata
|   |   |   `-- outbox
|   |   |-- ha_agent
|   |   |   |-- hosted-engine.lockspace -> /var/run/vdsm/storage/5628b18f-757e-4372-bc74-008f9be9ff3a/f029d285-6694-42aa-8e57-76936a375620/2941a0f6-87c1-4ab2-a024-78661d228248
|   |   |   `-- hosted-engine.metadata -> /var/run/vdsm/storage/5628b18f-757e-4372-bc74-008f9be9ff3a/a14d1c88-70c1-46b6-90b9-064dd41cc9b4/3ddc4f54-7049-4725-8a58-353f3f6d8576
|   |   `-- images
|   |       |-- 8c6419a8-768c-4029-950f-45561cd6e82a
|   |       |   |-- 13d6443c-5004-472e-b405-33e3fe1cf3a8
|   |       |   |-- 13d6443c-5004-472e-b405-33e3fe1cf3a8.lease
|   |       |   `-- 13d6443c-5004-472e-b405-33e3fe1cf3a8.meta
|   |       |-- a14d1c88-70c1-46b6-90b9-064dd41cc9b4
|   |       |   |-- 3ddc4f54-7049-4725-8a58-353f3f6d8576
|   |       |   |-- 3ddc4f54-7049-4725-8a58-353f3f6d8576.lease
|   |       |   `-- 3ddc4f54-7049-4725-8a58-353f3f6d8576.meta
|   |       |-- cf5c9a02-aa75-4399-8cad-a613e1fe7bf6
|   |       |   |-- 99ca821b-3c3b-49fc-9af1-677d6b486ccb
|   |       |   |-- 99ca821b-3c3b-49fc-9af1-677d6b486ccb.lease
|   |       |   `-- 99ca821b-3c3b-49fc-9af1-677d6b486ccb.meta
|   |       `-- f029d285-6694-42aa-8e57-76936a375620
|   |           |-- 2941a0f6-87c1-4ab2-a024-78661d228248
|   |           |-- 2941a0f6-87c1-4ab2-a024-78661d228248.lease
|   |           `-- 2941a0f6-87c1-4ab2-a024-78661d228248.meta
|   `-- __DIRECT_IO_TEST__
|-- blockSD
|   |-- 2d9a305f-392d-48c9-bd48-1a5fcdff6cc9
|   |   |-- dom_md
|   |   |   |-- ids -> /dev/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/ids
|   |   |   |-- inbox -> /dev/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/inbox
|   |   |   |-- leases -> /dev/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/leases
|   |   |   |-- master -> /dev/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/master
|   |   |   |-- metadata -> /dev/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/metadata
|   |   |   `-- outbox -> /dev/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/outbox
|   |   |-- ha_agent
|   |   `-- images
|   |       |-- aa8e3487-5ebd-4a33-b347-55277d266814
|   |       |   `-- bbbb9719-a7c3-428a-95ce-9597b4353650 -> /dev/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/bbbb9719-a7c3-428a-95ce-9597b4353650
|   |       `-- ab515f0c-f7d1-4047-bc8a-1acbe3c6da3e
|   |           `-- 4a357765-686e-41c6-8463-e52550f7218a -> /dev/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/4a357765-686e-41c6-8463-e52550f7218a
|   |-- 66c5a4b8-6446-4aa0-95df-26f825114ee9
|   |   |-- dom_md
|   |   |   |-- ids -> /dev/66c5a4b8-6446-4aa0-95df-26f825114ee9/ids
|   |   |   |-- inbox -> /dev/66c5a4b8-6446-4aa0-95df-26f825114ee9/inbox
|   |   |   |-- leases -> /dev/66c5a4b8-6446-4aa0-95df-26f825114ee9/leases
|   |   |   |-- master -> /dev/66c5a4b8-6446-4aa0-95df-26f825114ee9/master
|   |   |   |-- metadata -> /dev/66c5a4b8-6446-4aa0-95df-26f825114ee9/metadata
|   |   |   `-- outbox -> /dev/66c5a4b8-6446-4aa0-95df-26f825114ee9/outbox
|   |   |-- ha_agent
|   |   `-- images
|   |       |-- 581f977b-46ab-4bfd-82bd-d7d1e1e23f7b
|   |       |   `-- 914b6d5b-485a-46e0-aba5-73f3ea160b09 -> /dev/66c5a4b8-6446-4aa0-95df-26f825114ee9/914b6d5b-485a-46e0-aba5-73f3ea160b09
|   |       `-- 8da357eb-74eb-410e-8e4b-b5765acca6f7
|   |           `-- 2bbc23da-abdd-4c38-8485-edb6a086478f -> /dev/66c5a4b8-6446-4aa0-95df-26f825114ee9/2bbc23da-abdd-4c38-8485-edb6a086478f
|   |-- 8c095126-eef1-49a1-b1cd-1e30d1d0af8f
|   |   |-- dom_md
|   |   |   |-- ids -> /dev/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/ids
|   |   |   |-- inbox -> /dev/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/inbox
|   |   |   |-- leases -> /dev/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/leases
|   |   |   |-- master -> /dev/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/master
|   |   |   |-- metadata -> /dev/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/metadata
|   |   |   `-- outbox -> /dev/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/outbox
|   |   |-- ha_agent
|   |   `-- images
|   |       |-- a3a51a2c-9182-45b7-88dc-ffadc1ca0cad
|   |       |   `-- e3cde315-3472-4737-93ca-80bdded69ad4 -> /dev/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/e3cde315-3472-4737-93ca-80bdded69ad4
|   |       `-- dc47fe12-c71d-46e2-af08-b018384ffd54
|   |           `-- a0e9248e-62bd-4688-a902-482c4b871c7f -> /dev/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/a0e9248e-62bd-4688-a902-482c4b871c7f
|   `-- e31aef23-9472-406a-941f-7ae7ffe63d72
|       |-- dom_md
|       |   |-- ids -> /dev/e31aef23-9472-406a-941f-7ae7ffe63d72/ids
|       |   |-- inbox -> /dev/e31aef23-9472-406a-941f-7ae7ffe63d72/inbox
|       |   |-- leases -> /dev/e31aef23-9472-406a-941f-7ae7ffe63d72/leases
|       |   |-- master -> /dev/e31aef23-9472-406a-941f-7ae7ffe63d72/master
|       |   |-- metadata -> /dev/e31aef23-9472-406a-941f-7ae7ffe63d72/metadata
|       |   `-- outbox -> /dev/e31aef23-9472-406a-941f-7ae7ffe63d72/outbox
|       |-- ha_agent
|       `-- images
|           |-- 0d0853c8-72ae-4ee7-8690-d397c0f7fedd
|           |   `-- e8348f68-6f98-4691-b2d1-0d6ff1e32a5b -> /dev/e31aef23-9472-406a-941f-7ae7ffe63d72/e8348f68-6f98-4691-b2d1-0d6ff1e32a5b
|           `-- f9840ed0-2a70-41f8-9691-e1958cc6babd
|               `-- 04027290-bfba-450c-9cbc-72a41380a734 -> /dev/e31aef23-9472-406a-941f-7ae7ffe63d72/04027290-bfba-450c-9cbc-72a41380a734
|-- _var_lib_ovirt-hosted-engine-setup_tmpJHhHVp
|   |-- __DIRECT_IO_TEST__
|   `-- lost+found
|-- _var_lib_ovirt-hosted-engine-setup_tmpLyAGbp
|   |-- __DIRECT_IO_TEST__
|   `-- lost+found
|-- _var_lib_ovirt-hosted-engine-setup_tmpOmPTMu
|   |-- __DIRECT_IO_TEST__
|   `-- lost+found
|-- _var_lib_ovirt-hosted-engine-setup_tmpRmtLka
|   |-- __DIRECT_IO_TEST__
|   `-- lost+found
`-- _var_lib_ovirt-hosted-engine-setup_tmpUeFNii
    |-- __DIRECT_IO_TEST__
    `-- lost+found

44 directories, 57 files
Comment 1 Simone Tiraboschi 2015-11-05 09:43:56 EST
(In reply to Elad from comment #0)
> For iSCSI:
> 
> vdsm.log:
> 
> Thread-131::ERROR::2015-11-05
> 15:45:17,624::task::866::Storage.TaskManager.Task::(_setError)
> Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::Unexpected error
> Traceback (most recent call last):
>   File "/usr/share/vdsm/storage/task.py", line 873, in _run
>     return fn(*args, **kargs)
>   File "/usr/share/vdsm/logUtils.py", line 49, in wrapper
>     res = f(*args, **kwargs)
>   File "/usr/share/vdsm/storage/hsm.py", line 3214, in prepareImage
>     raise se.VolumeDoesNotExist(leafUUID)
> VolumeDoesNotExist: Volume does not exist:
> ('4a357765-686e-41c6-8463-e52550f7218a',)
> 


Just before it failed the host experimented iSCSI connectivity issues at kernel level so multipathd marked the path as down and so the device disappeared and from here the issue.
Look at /var/log/messages

Nov  5 15:45:15 green-vdsb kernel: blk_update_request: 14 callbacks suppressed
Nov  5 15:45:15 green-vdsb kernel: blk_update_request: I/O error, dev dm-26, sector 0
Nov  5 15:45:15 green-vdsb kernel: blk_update_request: I/O error, dev dm-26, sector 106954624
Nov  5 15:45:15 green-vdsb kernel: blk_update_request: I/O error, dev dm-26, sector 106954736
Nov  5 15:45:16 green-vdsb kernel: blk_update_request: I/O error, dev dm-26, sector 0
Nov  5 15:45:16 green-vdsb kernel: blk_update_request: I/O error, dev dm-26, sector 106954624
Nov  5 15:45:16 green-vdsb kernel: blk_update_request: I/O error, dev dm-26, sector 106954736
Nov  5 15:45:16 green-vdsb kernel: blk_update_request: I/O error, dev dm-26, sector 0
Nov  5 15:45:16 green-vdsb kernel: blk_update_request: I/O error, dev dm-26, sector 106954624
Nov  5 15:45:16 green-vdsb kernel: blk_update_request: I/O error, dev dm-26, sector 106954736
Nov  5 15:45:16 green-vdsb journal: vdsm root WARNING File: /rhev/data-center/940cf244-1bbc-4e7b-a23c-1816d255e6fa/2d9a305f-392d-48c9-bd48-1a5fcdff6cc9/images/aa8e3487-5ebd-4a33-b347-55277d266814/bbbb9719-a7c3-428a-95ce-9597b4353650 already removed
Nov  5 15:45:16 green-vdsb multipathd: 3514f0c5a51600857: sdu - directio checker reports path is down
Nov  5 15:45:16 green-vdsb kernel: blk_update_request: I/O error, dev dm-26, sector 0
Comment 2 Simone Tiraboschi 2015-11-05 09:48:11 EST
(In reply to Elad from comment #0)
> For FC:
> 
> vdsm.log:
> 
> Thread-107::ERROR::2015-11-05
> 15:26:36,897::task::866::Storage.TaskManager.Task::(_setError)
> Task=`cceb857e-7897-4ab6-9fb8-d7d7abedd943`::Unexpected error
> Traceback (most recent call last):
>   File "/usr/share/vdsm/storage/task.py", line 873, in _run
>     return fn(*args, **kargs)
>   File "/usr/share/vdsm/logUtils.py", line 49, in wrapper
>     res = f(*args, **kwargs)
>   File "/usr/share/vdsm/storage/hsm.py", line 3214, in prepareImage
>     raise se.VolumeDoesNotExist(leafUUID)
> VolumeDoesNotExist: Volume does not exist:
> ('e3cde315-3472-4737-93ca-80bdded69ad4',)
> 

The same here:

Nov  5 15:26:13 green-vdsb kernel: sd 4:0:0:0: [sdb] Read Capacity(10) failed: Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Nov  5 15:26:13 green-vdsb kernel: sd 4:0:0:0: [sdb] Sense Key : Illegal Request [current] 
Nov  5 15:26:13 green-vdsb kernel: sd 4:0:0:0: [sdb] Add. Sense: Logical unit not supported
Nov  5 15:26:13 green-vdsb kernel: sd 4:0:1:0: [sdc] Read Capacity(10) failed: Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Nov  5 15:26:13 green-vdsb kernel: sd 4:0:1:0: [sdc] Sense Key : Illegal Request [current] 
Nov  5 15:26:13 green-vdsb kernel: sd 4:0:1:0: [sdc] Add. Sense: Logical unit not supported
Nov  5 15:26:13 green-vdsb kernel: device-mapper: table: 253:26: multipath: error getting device
Nov  5 15:26:13 green-vdsb kernel: device-mapper: ioctl: error adding target to table
Nov  5 15:26:13 green-vdsb multipathd: dm-26: remove map (uevent)
Nov  5 15:26:13 green-vdsb multipathd: dm-26: remove map (uevent)
Nov  5 15:26:35 green-vdsb journal: vdsm root WARNING File: /rhev/data-center/a6276cdf-f029-461a-87b6-62099bf7d8bc/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/images/dc47fe12-c71d-46e2-af08-b018384ffd54/a0e9248e-62bd-4688-a902-482c4b871c7f already removed
Nov  5 15:26:35 green-vdsb multipathd: dm-26: remove map (uevent)
Nov  5 15:26:35 green-vdsb multipathd: dm-26: devmap not registered, can't remove
Nov  5 15:26:35 green-vdsb multipathd: dm-26: remove map (uevent)
Nov  5 15:26:36 green-vdsb systemd: Started Shared Storage Lease Manager.
Nov  5 15:26:37 green-vdsb journal: vdsm root WARNING File: /rhev/data-center/a6276cdf-f029-461a-87b6-62099bf7d8bc/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/images/a3a51a2c-9182-45b7-88dc-ffadc1ca0cad/e3cde315-3472-4737-93ca-80bdded69ad4 already removed
Nov  5 15:26:37 green-vdsb multipathd: dm-27: remove map (uevent)
Nov  5 15:26:37 green-vdsb multipathd: dm-27: devmap not registered, can't remove
Nov  5 15:26:37 green-vdsb multipathd: dm-27: remove map (uevent)


Can you please try using a different SAN?
Comment 3 Simone Tiraboschi 2015-11-05 12:02:07 EST
the prepareImage fails due to hardware issues in the connection with the SAN.
The issue is that hosted-engine-setup neither recognize it neither logs.

Nir, it's also the prepareImage an async task where we have to poll to get its status?
We are just getting its initial return code.

[root@green-vdsb ~]# grep 6ce7a9e3-bcce-4542-a127-9164831e0720 /var/log/vdsm/vdsm.log
Thread-131::DEBUG::2015-11-05 15:45:17,497::task::595::Storage.TaskManager.Task::(_updateState) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::moving from state init -> state preparing
Thread-131::DEBUG::2015-11-05 15:45:17,499::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::_resourcesAcquired: Storage.2d9a305f-392d-48c9-bd48-1a5fcdff6cc9 (shared)
Thread-131::DEBUG::2015-11-05 15:45:17,499::task::993::Storage.TaskManager.Task::(_decref) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::ref 1 aborting False
Thread-131::ERROR::2015-11-05 15:45:17,624::task::866::Storage.TaskManager.Task::(_setError) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::Unexpected error
Thread-131::DEBUG::2015-11-05 15:45:17,626::task::885::Storage.TaskManager.Task::(_run) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::Task._run: 6ce7a9e3-bcce-4542-a127-9164831e0720 ('2d9a305f-392d-48c9-bd48-1a5fcdff6cc9', '940cf244-1bbc-4e7b-a23c-1816d255e6fa', 'ab515f0c-f7d1-4047-bc8a-1acbe3c6da3e', '4a357765-686e-41c6-8463-e52550f7218a') {} failed - stopping task
Thread-131::DEBUG::2015-11-05 15:45:17,626::task::1246::Storage.TaskManager.Task::(stop) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::stopping in state preparing (force False)
Thread-131::DEBUG::2015-11-05 15:45:17,626::task::993::Storage.TaskManager.Task::(_decref) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::ref 1 aborting True
Thread-131::INFO::2015-11-05 15:45:17,627::task::1171::Storage.TaskManager.Task::(prepare) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::aborting: Task is aborted: 'Volume does not exist' - code 201
Thread-131::DEBUG::2015-11-05 15:45:17,627::task::1176::Storage.TaskManager.Task::(prepare) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::Prepare: aborted: Volume does not exist
Thread-131::DEBUG::2015-11-05 15:45:17,627::task::993::Storage.TaskManager.Task::(_decref) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::ref 0 aborting True
Thread-131::DEBUG::2015-11-05 15:45:17,627::task::928::Storage.TaskManager.Task::(_doAbort) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::Task._doAbort: force False
Thread-131::DEBUG::2015-11-05 15:45:17,627::task::595::Storage.TaskManager.Task::(_updateState) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::moving from state preparing -> state aborting
Thread-131::DEBUG::2015-11-05 15:45:17,627::task::550::Storage.TaskManager.Task::(__state_aborting) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::_aborting: recover policy none
Thread-131::DEBUG::2015-11-05 15:45:17,627::task::595::Storage.TaskManager.Task::(_updateState) Task=`6ce7a9e3-bcce-4542-a127-9164831e0720`::moving from state aborting -> state failed
Comment 4 Simone Tiraboschi 2015-11-06 07:37:44 EST
Ok, I got it, it was not that evident cause our logging is not that good on that path.

We call prepareImage once waiting for a 201 or 254 error to ensure that the volume doesn't exists.
Then createVolume and than the prepareImage for the second time.
What I saw in vdsm logs is the first prepareImage that is failing and it's expected; the createVolume and the subsequent prepareImage was correct.

The issue is that at the end we fails on 

IOError: [Errno 13] Permission denied: '/var/run/vdsm/storage/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/a3a51a2c-9182-45b7-88dc-ffadc1ca0cad/e3cde315-3472-4737-93ca-80bdded69ad4'
2015-11-05 15:26:38 ERROR otopi.context context._executeMethod:165 Failed to execute stage 'Misc configuration': [Errno 13] Permission denied: '/var/run/vdsm/storage/8c095126-eef1-49a1-b1cd-1e30d1d0af8f/a3a51a2c-9
182-45b7-88dc-ffadc1ca0cad/e3cde315-3472-4737-93ca-80bdded69ad4'


cause the symlink on /var/run/vdsm/storage/ is there and it's pointing to an existing device but permission issues on that device.

The issue is reproducible on this host where we have IOErrors at kernel level while it's not reproducible on other hosts.
Comment 5 Sandro Bonazzola 2015-11-17 07:11:19 EST
Dropping blocker flag being this an environmental issue limited to a host having sotrage kernel issues.
Comment 6 Sandro Bonazzola 2015-11-17 07:11:55 EST
I'm also proposing to close this as not a bug, being permission denied the correct error.
Comment 7 Sandro Bonazzola 2015-11-17 07:12:43 EST
Please reopen if you think there's a real bug here.

Note You need to log in before you can comment on or make changes to this bug.